data race in various middlewares

[gsparx]

I'm able to consistently induce the golang race detector to detect data race in several middleware

In the DefaultDevStack (likely not expected to be used in production code)

==================
WARNING: DATA RACE
Read at 0x000000b1a0b0 by goroutine 8:
  github.com/ant0ine/go-json-rest/rest.(*JsonIndentMiddleware).MiddlewareFunc()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/json_indent.go:27 +0x48
  github.com/ant0ine/go-json-rest/rest.WrapMiddlewares()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/middleware.go:46 +0x92
  github.com/ant0ine/go-json-rest/rest.(*Api).MakeHandler()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/api.go:44 +0x9f
  go_json_rest_race_test.TestSimulReads.func2()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:23 +0x3c

Previous write at 0x000000b1a0b0 by goroutine 7:
  github.com/ant0ine/go-json-rest/rest.(*JsonIndentMiddleware).MiddlewareFunc()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/json_indent.go:28 +0x156
  github.com/ant0ine/go-json-rest/rest.WrapMiddlewares()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/middleware.go:46 +0x92
  github.com/ant0ine/go-json-rest/rest.(*Api).MakeHandler()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/api.go:44 +0x9f
  go_json_rest_race_test.TestSimulReads.func1()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:15 +0x3c

Goroutine 8 (running) created at:
  go_json_rest_race_test.TestSimulReads()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:28 +0x8f
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:657 +0x107

Goroutine 7 (running) created at:
  go_json_rest_race_test.TestSimulReads()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:20 +0x63
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:657 +0x107
==================
==================
WARNING: DATA RACE
Read at 0x000000b0fcf0 by goroutine 8:
  github.com/ant0ine/go-json-rest/rest.(*RecoverMiddleware).MiddlewareFunc()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/recover.go:32 +0x3f
  github.com/ant0ine/go-json-rest/rest.WrapMiddlewares()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/middleware.go:46 +0x92
  github.com/ant0ine/go-json-rest/rest.(*Api).MakeHandler()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/api.go:44 +0x9f
  go_json_rest_race_test.TestSimulReads.func2()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:23 +0x3c

Previous write at 0x000000b0fcf0 by goroutine 7:
  github.com/ant0ine/go-json-rest/rest.(*RecoverMiddleware).MiddlewareFunc()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/recover.go:33 +0x243
  github.com/ant0ine/go-json-rest/rest.WrapMiddlewares()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/middleware.go:46 +0x92
  github.com/ant0ine/go-json-rest/rest.(*Api).MakeHandler()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/api.go:44 +0x9f
  go_json_rest_race_test.TestSimulReads.func1()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:15 +0x3c

Goroutine 8 (running) created at:
  go_json_rest_race_test.TestSimulReads()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:28 +0x8f
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:657 +0x107

Goroutine 7 (running) created at:
  go_json_rest_race_test.TestSimulReads()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:20 +0x63
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:657 +0x107
==================
==================
WARNING: DATA RACE
Read at 0x000000b1a080 by goroutine 8:
  github.com/ant0ine/go-json-rest/rest.(*AccessLogApacheMiddleware).MiddlewareFunc()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/access_log_apache.go:74 +0x3f
  github.com/ant0ine/go-json-rest/rest.WrapMiddlewares()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/middleware.go:46 +0x92
  github.com/ant0ine/go-json-rest/rest.(*Api).MakeHandler()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/api.go:44 +0x9f
  go_json_rest_race_test.TestSimulReads.func2()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:23 +0x3c

Previous write at 0x000000b1a080 by goroutine 7:
  github.com/ant0ine/go-json-rest/rest.(*AccessLogApacheMiddleware).MiddlewareFunc()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/access_log_apache.go:75 +0x2cf
  github.com/ant0ine/go-json-rest/rest.WrapMiddlewares()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/middleware.go:46 +0x92
  github.com/ant0ine/go-json-rest/rest.(*Api).MakeHandler()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/api.go:44 +0x9f
  go_json_rest_race_test.TestSimulReads.func1()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:15 +0x3c

Goroutine 8 (running) created at:
  go_json_rest_race_test.TestSimulReads()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:28 +0x8f
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:657 +0x107

Goroutine 7 (running) created at:
  go_json_rest_race_test.TestSimulReads()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:20 +0x63
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:657 +0x107
==================
==================
WARNING: DATA RACE
Read at 0x000000b1a088 by goroutine 8:
  github.com/ant0ine/go-json-rest/rest.(*AccessLogApacheMiddleware).MiddlewareFunc()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/access_log_apache.go:79 +0x65
  github.com/ant0ine/go-json-rest/rest.WrapMiddlewares()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/middleware.go:46 +0x92
  github.com/ant0ine/go-json-rest/rest.(*Api).MakeHandler()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/api.go:44 +0x9f
  go_json_rest_race_test.TestSimulReads.func2()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:23 +0x3c

Previous write at 0x000000b1a088 by goroutine 7:
  github.com/ant0ine/go-json-rest/rest.(*AccessLogApacheMiddleware).MiddlewareFunc()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/access_log_apache.go:80 +0x17c
  github.com/ant0ine/go-json-rest/rest.WrapMiddlewares()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/middleware.go:46 +0x92
  github.com/ant0ine/go-json-rest/rest.(*Api).MakeHandler()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/api.go:44 +0x9f
  go_json_rest_race_test.TestSimulReads.func1()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:15 +0x3c

Goroutine 8 (running) created at:
  go_json_rest_race_test.TestSimulReads()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:28 +0x8f
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:657 +0x107

Goroutine 7 (running) created at:
  go_json_rest_race_test.TestSimulReads()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:20 +0x63
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:657 +0x107
==================
FAIL
exit status 1
FAIL	go_json_rest_race_test	0.020s

and in the DefaultCommonStack (seems like this should be viable for production)

==================
WARNING: DATA RACE
Read at 0x000000ab58d0 by goroutine 8:
  github.com/ant0ine/go-json-rest/rest.(*RecoverMiddleware).MiddlewareFunc()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/recover.go:32 +0x3f
  github.com/ant0ine/go-json-rest/rest.WrapMiddlewares()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/middleware.go:46 +0x92
  github.com/ant0ine/go-json-rest/rest.(*Api).MakeHandler()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/api.go:44 +0x9f
  go_json_rest_race_test.TestSimulReads.func2()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:23 +0x3c

Previous write at 0x000000ab58d0 by goroutine 7:
  github.com/ant0ine/go-json-rest/rest.(*RecoverMiddleware).MiddlewareFunc()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/recover.go:33 +0x243
  github.com/ant0ine/go-json-rest/rest.WrapMiddlewares()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/middleware.go:46 +0x92
  github.com/ant0ine/go-json-rest/rest.(*Api).MakeHandler()
      /home/garretts/dev/go/src/github.com/ant0ine/go-json-rest/rest/api.go:44 +0x9f
  go_json_rest_race_test.TestSimulReads.func1()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:15 +0x3c

Goroutine 8 (running) created at:
  go_json_rest_race_test.TestSimulReads()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:28 +0x8f
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:657 +0x107

Goroutine 7 (running) created at:
  go_json_rest_race_test.TestSimulReads()
      /home/garretts/dev/go/src/go_json_rest_race_test/race_test.go:20 +0x63
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:657 +0x107
==================
Reading data
Reading data
FAIL
exit status 1
FAIL	go_json_rest_race_test	0.016s

Just based on the naming, it seems like RecoverMiddleware is non-optional. If it is optional, is there a middleware stack that you would suggest running in production that is not susceptible to data races?

Code is attached (it's basically just the HelloWorld example plus a test). Runnable with go test -race

Thanks!

go_json_rest_race_test.tar.gz

[ant0ine]

Hi @gsparx !

Thanks for your bug report! And sorry for my extremely slow response. I didn't have much time for this project in a past few months. I'm not very familiar with the go test -race, but it looks very useful. And I did run your test and reproduced the output.

But I noticed that your test is instantiating the API handler twice. One in each go routine. I think this is where the problem is. A single API object with a single stack of middlewares, but with MakeHandler() called multiple times in a concurrent way.

The middlewares are "initialized" by calling MiddlewareFunc for each of them. They are not supposed to run for each request in a concurrent way because the state of each middleware objects would be shared between the go routines.

I think that a more realistic test is to instantiate the API stack of middlewares once, and to run concurrent requests. In that case the test passes.

func TestSimulReads(t *testing.T) {
    var api *rest.Api
    api, _ = registerRoutes()
    h := api.MakeHandler()

  f := func() {
    recorded := test.RunRequest(t, h,
      test.MakeSimpleRequest("GET", "/", nil),
    )
    recorded.CodeIs(200)
    recorded.ContentTypeIsJson()
  }
  go f()
  go f()
}

Now, I dug a bit further and found something else. The following code instantiates a full new API object in each go routine (which in practice doesn't make much sense), and fails go test -race.

func TestSimulReads(t *testing.T) {

  f := func() {
    api := rest.NewApi()
    api.Use(rest.DefaultCommonStack...)
    router, _ := rest.MakeRouter(
      rest.Get("/", GetData),
    )
    api.SetApp(router)
    recorded := test.RunRequest(t, api.MakeHandler(),
      test.MakeSimpleRequest("GET", "/", nil),
    )
    recorded.CodeIs(200)
    recorded.ContentTypeIsJson()
  }

  go f()
  go f()
}

This is because the stack of middlewares is actually instantiated as a global variable rest.DefaultCommonStack (see https://github.com/ant0ine/go-json-rest/blob/master/rest/api.go#L51), making these middlewares shared between the two API objects and the two go routines.

Replacing the global variable by the actual instantiations of the middlewares works:

func TestSimulReads(t *testing.T) {

  f := func() {
    api := rest.NewApi()
    api.Use(
        &rest.TimerMiddleware{},
        &rest.RecorderMiddleware{},
        &rest.PoweredByMiddleware{},
        &rest.RecoverMiddleware{},
    )
    router, _ := rest.MakeRouter(
      rest.Get("/", GetData),
    )
    api.SetApp(router)
    recorded := test.RunRequest(t, api.MakeHandler(),
      test.MakeSimpleRequest("GET", "/", nil),
    )
    recorded.CodeIs(200)
    recorded.ContentTypeIsJson()
  }

  go f()
  go f()
}

I guess the fix would be to replace these set of global variables: DefaultDevStack, DefaultProdStack, and DefaultCommonStack by a set of functions instantiating a new middleware objects at each call. (eg; MakeDefaultDevStack, ...)

That is obviously a breaking API change.

Any thought ?