nautilus/gateway

Data races, some between logger and execution

JohnStarich opened this issue · 7 comments

JohnStarich commented

Hey there! I've hit a couple race conditions with the logger during execution. It seems some of the same data used in log fields are also mutated in another goroutine at the same time.

I've included the output of go test -race ./... on master below:

Click to expand full log:

WARNING: DATA RACE
Read at 0x00c0001b0750 by goroutine 67:
  github.com/nautilus/graphql.formatSelection()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:37 +0x19c
  github.com/nautilus/graphql.FormatSelectionSet()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:57 +0x46
  github.com/nautilus/gateway.(*DefaultLogger).QueryPlanStep()
      /tmp/gateway/logging.go:79 +0x28b
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:160 +0x3d3
  github.com/nautilus/gateway.executeStep.func1·dwrap·6()
      /tmp/gateway/execute.go:268 +0x10b

Previous write at 0x00c0001b0750 by goroutine 66:
  github.com/nautilus/graphql.collectFields()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:144 +0x20a
  github.com/nautilus/graphql.ApplyFragments()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:47 +0xd6
  github.com/nautilus/gateway.findSelection()
      /tmp/gateway/execute.go:316 +0x90
  github.com/nautilus/gateway.executorFindInsertionPoints()
      /tmp/gateway/execute.go:365 +0x5d7
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:280 +0x1bec
  github.com/nautilus/gateway.executeStep.func1·dwrap·6()
      /tmp/gateway/execute.go:268 +0x10b

==================
WARNING: DATA RACE
Read at 0x00c00015b440 by goroutine 17:
  runtime.mapaccess2_faststr()
      /usr/local/Cellar/go/1.17/libexec/src/runtime/map_faststr.go:107 +0x0
  github.com/nautilus/gateway.(*AutomaticQueryPlanCache).Retrieve()
      /tmp/gateway/cache.go:179 +0x12c
  github.com/nautilus/gateway.TestAutomaticQueryPlanCache_garbageCollection()
      /tmp/gateway/cache_test.go:182 +0x5e9
  testing.tRunner()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1306 +0x47

Previous write at 0x00c00015b440 by goroutine 18:
  runtime.mapdelete_faststr()
      /usr/local/Cellar/go/1.17/libexec/src/runtime/map_faststr.go:300 +0x0
  github.com/nautilus/gateway.(*AutomaticQueryPlanCache).Retrieve.func1.1()
      /tmp/gateway/cache.go:166 +0x40c

Goroutine 17 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1306 +0x726
  testing.runTests.func1()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1598 +0x99
  testing.tRunner()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1259 +0x22f
  testing.runTests()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1596 +0x7ca
  testing.(*M).Run()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1504 +0x9d1
  main.main()
      _testmain.go:201 +0x22b

Goroutine 18 (finished) created at:
  github.com/nautilus/gateway.(*AutomaticQueryPlanCache).Retrieve.func1()
      /tmp/gateway/cache.go:125 +0x98
  github.com/nautilus/gateway.(*AutomaticQueryPlanCache).Retrieve()
      /tmp/gateway/cache.go:214 +0x618
  github.com/nautilus/gateway.TestAutomaticQueryPlanCache_garbageCollection()
      /tmp/gateway/cache_test.go:167 +0x376
  testing.tRunner()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1306 +0x47
==================
==================
WARNING: DATA RACE
Write at 0x00c00015fc28 by goroutine 17:
  github.com/nautilus/gateway.(*AutomaticQueryPlanCache).Retrieve()
      /tmp/gateway/cache.go:208 +0x5ac
  github.com/nautilus/gateway.TestAutomaticQueryPlanCache_garbageCollection()
      /tmp/gateway/cache_test.go:182 +0x5e9
  testing.tRunner()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1306 +0x47

Previous read at 0x00c00015fc28 by goroutine 18:
  github.com/nautilus/gateway.(*AutomaticQueryPlanCache).Retrieve.func1.1()
      /tmp/gateway/cache.go:162 +0x325

Goroutine 17 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1306 +0x726
  testing.runTests.func1()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1598 +0x99
  testing.tRunner()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1259 +0x22f
  testing.runTests()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1596 +0x7ca
  testing.(*M).Run()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1504 +0x9d1
  main.main()
      _testmain.go:201 +0x22b

Goroutine 18 (finished) created at:
  github.com/nautilus/gateway.(*AutomaticQueryPlanCache).Retrieve.func1()
      /tmp/gateway/cache.go:125 +0x98
  github.com/nautilus/gateway.(*AutomaticQueryPlanCache).Retrieve()
      /tmp/gateway/cache.go:214 +0x618
  github.com/nautilus/gateway.TestAutomaticQueryPlanCache_garbageCollection()
      /tmp/gateway/cache_test.go:167 +0x376
  testing.tRunner()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/local/Cellar/go/1.17/libexec/src/testing/testing.go:1306 +0x47
==================
--- FAIL: TestAutomaticQueryPlanCache_garbageCollection (0.15s)
    testing.go:1152: race detected during execution of test
==================
WARNING: DATA RACE
Read at 0x00c0001b0750 by goroutine 67:
  github.com/nautilus/graphql.formatSelection()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:37 +0x19c
  github.com/nautilus/graphql.FormatSelectionSet()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:57 +0x46
  github.com/nautilus/gateway.(*DefaultLogger).QueryPlanStep()
      /tmp/gateway/logging.go:79 +0x28b
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:160 +0x3d3
  github.com/nautilus/gateway.executeStep.func1·dwrap·6()
      /tmp/gateway/execute.go:268 +0x10b

Previous write at 0x00c0001b0750 by goroutine 66:
  github.com/nautilus/graphql.collectFields()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:144 +0x20a
  github.com/nautilus/graphql.ApplyFragments()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:47 +0xd6
  github.com/nautilus/gateway.findSelection()
      /tmp/gateway/execute.go:316 +0x90
  github.com/nautilus/gateway.executorFindInsertionPoints()
      /tmp/gateway/execute.go:365 +0x5d7
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:280 +0x1bec
  github.com/nautilus/gateway.executeStep.func1·dwrap·6()
      /tmp/gateway/execute.go:268 +0x10b

Goroutine 67 (running) created at:
  github.com/nautilus/gateway.executeStep.func1()
      /tmp/gateway/execute.go:268 +0x4e4
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:306 +0x1f6a
  github.com/nautilus/gateway.(*ParallelExecutor).Execute·dwrap·4()
      /tmp/gateway/execute.go:77 +0x10b

Goroutine 66 (running) created at:
  github.com/nautilus/gateway.executeStep.func1()
      /tmp/gateway/execute.go:268 +0x4e4
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:306 +0x1f6a
  github.com/nautilus/gateway.(*ParallelExecutor).Execute·dwrap·4()
      /tmp/gateway/execute.go:77 +0x10b
==================
==================
WARNING: DATA RACE
Read at 0x00c0001a2e30 by goroutine 68:
  github.com/nautilus/graphql.formatSelection()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:31 +0xc5
  github.com/nautilus/graphql.formatSelectionSelectionSet()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:22 +0x52
  github.com/nautilus/graphql.formatSelection()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:38 +0x1e5
  github.com/nautilus/graphql.FormatSelectionSet()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:57 +0x46
  github.com/nautilus/gateway.(*DefaultLogger).QueryPlanStep()
      /tmp/gateway/logging.go:79 +0x28b
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:160 +0x3d3
  github.com/nautilus/gateway.executeStep.func1·dwrap·6()
      /tmp/gateway/execute.go:268 +0x10b

Previous write at 0x00c0001a2e30 by goroutine 66:
  github.com/nautilus/graphql.collectFields()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:140 +0x3b7
  github.com/nautilus/graphql.ApplyFragments()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:47 +0xd6
  github.com/nautilus/gateway.findSelection()
      /tmp/gateway/execute.go:316 +0x90
  github.com/nautilus/gateway.executorFindInsertionPoints()
      /tmp/gateway/execute.go:365 +0x5d7
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:280 +0x1bec
  github.com/nautilus/gateway.executeStep.func1·dwrap·6()
      /tmp/gateway/execute.go:268 +0x10b

Goroutine 68 (running) created at:
  github.com/nautilus/gateway.executeStep.func1()
      /tmp/gateway/execute.go:268 +0x4e4
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:306 +0x1f6a
  github.com/nautilus/gateway.(*ParallelExecutor).Execute·dwrap·4()
      /tmp/gateway/execute.go:77 +0x10b

Goroutine 66 (running) created at:
  github.com/nautilus/gateway.executeStep.func1()
      /tmp/gateway/execute.go:268 +0x4e4
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:306 +0x1f6a
  github.com/nautilus/gateway.(*ParallelExecutor).Execute·dwrap·4()
      /tmp/gateway/execute.go:77 +0x10b
==================
==================
WARNING: DATA RACE
Read at 0x00c0001b06d0 by goroutine 67:
  github.com/nautilus/graphql.formatSelection()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:37 +0x19c
  github.com/nautilus/graphql.formatSelectionSelectionSet()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:22 +0x52
  github.com/nautilus/graphql.formatSelection()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:38 +0x1e5
  github.com/nautilus/graphql.FormatSelectionSet()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/format.go:57 +0x46
  github.com/nautilus/gateway.(*DefaultLogger).QueryPlanStep()
      /tmp/gateway/logging.go:79 +0x28b
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:160 +0x3d3
  github.com/nautilus/gateway.executeStep.func1·dwrap·6()
      /tmp/gateway/execute.go:268 +0x10b

Previous write at 0x00c0001b06d0 by goroutine 66:
  github.com/nautilus/graphql.collectFields()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:144 +0x20a
  github.com/nautilus/graphql.ApplyFragments()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:47 +0xd6
  github.com/nautilus/gateway.findSelection()
      /tmp/gateway/execute.go:316 +0x90
  github.com/nautilus/gateway.executorFindInsertionPoints()
      /tmp/gateway/execute.go:365 +0x5d7
  github.com/nautilus/gateway.executorFindInsertionPoints()
      /tmp/gateway/execute.go:456 +0x1437
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:280 +0x1bec
  github.com/nautilus/gateway.executeStep.func1·dwrap·6()
      /tmp/gateway/execute.go:268 +0x10b

Goroutine 67 (running) created at:
  github.com/nautilus/gateway.executeStep.func1()
      /tmp/gateway/execute.go:268 +0x4e4
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:306 +0x1f6a
  github.com/nautilus/gateway.(*ParallelExecutor).Execute·dwrap·4()
      /tmp/gateway/execute.go:77 +0x10b

Goroutine 66 (running) created at:
  github.com/nautilus/gateway.executeStep.func1()
      /tmp/gateway/execute.go:268 +0x4e4
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:306 +0x1f6a
  github.com/nautilus/gateway.(*ParallelExecutor).Execute·dwrap·4()
      /tmp/gateway/execute.go:77 +0x10b
==================
==================
WARNING: DATA RACE
Read at 0x00c000330110 by goroutine 69:
  github.com/nautilus/graphql.collectFields()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:67 +0x494
  github.com/nautilus/graphql.collectFields()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:132 +0x188
  github.com/nautilus/graphql.ApplyFragments()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:47 +0xd6
  github.com/nautilus/gateway.findSelection()
      /tmp/gateway/execute.go:316 +0x90
  github.com/nautilus/gateway.executorFindInsertionPoints()
      /tmp/gateway/execute.go:365 +0x5d7
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:280 +0x1bec
  github.com/nautilus/gateway.executeStep.func1·dwrap·6()
      /tmp/gateway/execute.go:268 +0x10b

Previous write at 0x00c000330110 by goroutine 68:
  github.com/nautilus/graphql.collectFields()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:140 +0x3b7
  github.com/nautilus/graphql.ApplyFragments()
      $GOPATH/pkg/mod/github.com/nautilus/graphql@v0.0.16/language.go:47 +0xd6
  github.com/nautilus/gateway.findSelection()
      /tmp/gateway/execute.go:316 +0x90
  github.com/nautilus/gateway.executorFindInsertionPoints()
      /tmp/gateway/execute.go:365 +0x5d7
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:280 +0x1bec
  github.com/nautilus/gateway.executeStep.func1·dwrap·6()
      /tmp/gateway/execute.go:268 +0x10b

Goroutine 69 (running) created at:
  github.com/nautilus/gateway.executeStep.func1()
      /tmp/gateway/execute.go:268 +0x4e4
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:306 +0x1f6a
  github.com/nautilus/gateway.(*ParallelExecutor).Execute·dwrap·4()
      /tmp/gateway/execute.go:77 +0x10b

Goroutine 68 (finished) created at:
  github.com/nautilus/gateway.executeStep.func1()
      /tmp/gateway/execute.go:268 +0x4e4
  github.com/nautilus/gateway.executeStep()
      /tmp/gateway/execute.go:306 +0x1f6a
  github.com/nautilus/gateway.(*ParallelExecutor).Execute·dwrap·4()
      /tmp/gateway/execute.go:77 +0x10b
==================
--- FAIL: TestExecutor_insertIntoLists (0.00s)
    testing.go:1152: race detected during execution of test
�[33mWARNING�[0m Network Error: message                       
�[33mWARNING�[0m Network Error: message. message              
{"data":{"uploadInputWrapper":"file-id"}}
FAIL
FAIL	github.com/nautilus/gateway	1.245s
FAIL

I took a crack at it today, but I'm not much of an expert in the gateway's internals – so not super sure which struct state changes can be updated without introducing a new bug by mistake.

I managed to fix several of the data races by removing the func body from each logger method, so that might be a good starting point to root them out.

I'd be happy to contribute some fixes, but I may need a little help figuring out the invariants to maintain. Any ideas?

JohnStarich commented

Ha, I spoke too soon. 🙂 I dug into it further and found the primary source of races were in the graphql lib fragment resolver! Opened up nautilus/graphql#20

The other race appears to be in the cache, that one seems a bit easier to fix.

JohnStarich commented

Hey @AlecAivazis, friendly poke! 👋

When you have a second, curious what you think of these 2 PRs?

AlecAivazis commented

Sorry this has taken me a bit, I'm trying to understand the changes - it seems like every time someone fixes a race condition another one is introduced so Ii need to be dililgent when accepting changes

JohnStarich commented

Totally understand, thank you for looking it over!

I hope I've addressed those issues, that was my intent 😄 I've added a few test cases for async behavior and enabled the -race detector in both CI systems, so that should help a bit long-term too.

JohnStarich commented

If it helps, for nautilus/graphql#20 the primary change was converting the fragment resolver to a small, immutable data structure. The idea there was to minimize mutations of existing ast objects, then create shallow copies at the very end.

JohnStarich commented

Thanks @AlecAivazis! Would you mind cutting a new release tag with the change?

I noticed your call for more maintainers. I'd be interested in helping out where I can ❤️

AlecAivazis commented

Whoops! sorry about that. it should be released as 0.2.1

  • ❤️1