Race conditions in `graphql` and `bridge/github` packages (or package tests) | Bug da92341

Steve Moyer (smoyer64) opened 3 years ago

While trying to track down the problem with concurrent tests on Windows as described by #809, I ran the tests (Debian Bullseye and Go 1.18.3) with race detection enabled. Two different issues were found. The following command was run against the master branch at commit 96327c33:

go test -race ./...

In the graphql package, the following race condition was reported:

Building identity cache... Done.
Building bug cache... Done.
==================
WARNING: DATA RACE
Write at 0x00c0001b4998 by goroutine 30:
  github.com/MichaelMure/git-bug/api/graphql/models.(*lazyBug).load()
      /home/smoyer1/git/git-bug/api/graphql/models/lazy_bug.go:64 +0x144
  github.com/MichaelMure/git-bug/api/graphql/models.(*lazyBug).Operations()
      /home/smoyer1/git/git-bug/api/graphql/models/lazy_bug.go:148 +0x30
  github.com/MichaelMure/git-bug/api/graphql/resolvers.bugResolver.Operations()
      /home/smoyer1/git/git-bug/api/graphql/resolvers/bug.go:88 +0x72
  github.com/MichaelMure/git-bug/api/graphql/resolvers.(*bugResolver).Operations()
      <autogenerated>:1 +0xb7
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext)._Bug_operations.func2()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:4563 +0x28d
  github.com/99designs/gqlgen/graphql/executor.processExtensions.func4()
      /home/smoyer1/go/pkg/mod/github.com/99designs/gqlgen@v0.17.1/graphql/executor/extensions.go:72 +0x41
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext)._Bug_operations()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:4561 +0x6cd
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext)._Bug.func20()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:12159 +0x159
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext)._Bug.func21()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:12167 +0x4c
  github.com/99designs/gqlgen/graphql.(*FieldSet).Dispatch.func1()
      /home/smoyer1/go/pkg/mod/github.com/99designs/gqlgen@v0.17.1/graphql/fieldset.go:42 +0x4e
  github.com/99designs/gqlgen/graphql.(*FieldSet).Dispatch.func2()
      /home/smoyer1/go/pkg/mod/github.com/99designs/gqlgen@v0.17.1/graphql/fieldset.go:44 +0x58

Previous read at 0x00c0001b4998 by goroutine 29:
  github.com/MichaelMure/git-bug/api/graphql/models.(*lazyBug).load()
      /home/smoyer1/git/git-bug/api/graphql/models/lazy_bug.go:52 +0x5e
  github.com/MichaelMure/git-bug/api/graphql/models.(*lazyBug).Comments()
      /home/smoyer1/git/git-bug/api/graphql/models/lazy_bug.go:96 +0x30
  github.com/MichaelMure/git-bug/api/graphql/resolvers.bugResolver.Comments()
      /home/smoyer1/git/git-bug/api/graphql/resolvers/bug.go:56 +0x72
  github.com/MichaelMure/git-bug/api/graphql/resolvers.(*bugResolver).Comments()
      <autogenerated>:1 +0xb7
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext)._Bug_comments.func2()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:4479 +0x28d
  github.com/99designs/gqlgen/graphql/executor.processExtensions.func4()
      /home/smoyer1/go/pkg/mod/github.com/99designs/gqlgen@v0.17.1/graphql/executor/extensions.go:72 +0x41
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext)._Bug_comments()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:4477 +0x6cd
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext)._Bug.func16()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:12119 +0x159
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext)._Bug.func17()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:12127 +0x4c
  github.com/99designs/gqlgen/graphql.(*FieldSet).Dispatch.func1()
      /home/smoyer1/go/pkg/mod/github.com/99designs/gqlgen@v0.17.1/graphql/fieldset.go:42 +0x4e
  github.com/99designs/gqlgen/graphql.(*FieldSet).Dispatch.func2()
      /home/smoyer1/go/pkg/mod/github.com/99designs/gqlgen@v0.17.1/graphql/fieldset.go:44 +0x58

Goroutine 30 (running) created at:
  github.com/99designs/gqlgen/graphql.(*FieldSet).Dispatch()
      /home/smoyer1/go/pkg/mod/github.com/99designs/gqlgen@v0.17.1/graphql/fieldset.go:41 +0x51b
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext)._Bug()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:12174 +0x2f2
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext).marshalNBug2githubᚗcomᚋMichaelMureᚋgitᚑbugᚋapiᚋgraphqlᚋmodelsᚐBugWrapper()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:15386 +0x164
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext).marshalNBug2ᚕgithubᚗcomᚋMichaelMureᚋgitᚑbugᚋapiᚋgraphqlᚋmodelsᚐBugWrapperᚄ.func1()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:15413 +0x207
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext).marshalNBug2ᚕgithubᚗcomᚋMichaelMureᚋgitᚑbugᚋapiᚋgraphqlᚋmodelsᚐBugWrapperᚄ.func2()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:15418 +0x47

Goroutine 29 (running) created at:
  github.com/99designs/gqlgen/graphql.(*FieldSet).Dispatch()
      /home/smoyer1/go/pkg/mod/github.com/99designs/gqlgen@v0.17.1/graphql/fieldset.go:41 +0x51b
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext)._Bug()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:12174 +0x2f2
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext).marshalNBug2githubᚗcomᚋMichaelMureᚋgitᚑbugᚋapiᚋgraphqlᚋmodelsᚐBugWrapper()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:15386 +0x164
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext).marshalNBug2ᚕgithubᚗcomᚋMichaelMureᚋgitᚑbugᚋapiᚋgraphqlᚋmodelsᚐBugWrapperᚄ.func1()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:15413 +0x207
  github.com/MichaelMure/git-bug/api/graphql/graph.(*executionContext).marshalNBug2ᚕgithubᚗcomᚋMichaelMureᚋgitᚑbugᚋapiᚋgraphqlᚋmodelsᚐBugWrapperᚄ.func2()
      /home/smoyer1/git/git-bug/api/graphql/graph/gen_graph.go:15418 +0x47
==================
--- FAIL: TestQueries (7.98s)
    testing.go:1312: race detected during execution of test
FAIL
FAIL    github.com/MichaelMure/git-bug/api/graphql      8.217s

In the bridge/github package, the following race condition was found:

Building identity cache... Done.
Building bug cache... Done.
==================
WARNING: DATA RACE
Write at 0x00c000520910 by goroutine 51:
  runtime.closechan()
      /opt/go/1.18.3/src/runtime/chan.go:356 +0x0
  github.com/MichaelMure/git-bug/bridge/github.NewImportMediator.func1()
      /home/smoyer1/git/git-bug/bridge/github/import_mediator.go:92 +0x68

Previous read at 0x00c000520910 by goroutine 55:
  runtime.chansend()
      /opt/go/1.18.3/src/runtime/chan.go:159 +0x0
  github.com/MichaelMure/git-bug/bridge/github.(*rateLimitHandlerClient).queryWithImportEvents.func1()
      /home/smoyer1/git/git-bug/bridge/github/client.go:78 +0x144

Goroutine 51 (running) created at:
  github.com/MichaelMure/git-bug/bridge/github.NewImportMediator()
      /home/smoyer1/git/git-bug/bridge/github/import_mediator.go:90 +0x237
  github.com/MichaelMure/git-bug/bridge/github.(*githubImporter).ImportAll()
      /home/smoyer1/git/git-bug/bridge/github/import.go:55 +0x19c
  github.com/MichaelMure/git-bug/bridge/github.TestGithubImporterIntegration()
      /home/smoyer1/git/git-bug/bridge/github/import_integration_test.go:44 +0x3db
  testing.tRunner()
      /opt/go/1.18.3/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/go/1.18.3/src/testing/testing.go:1486 +0x47

Goroutine 55 (finished) created at:
  github.com/MichaelMure/git-bug/bridge/github.(*rateLimitHandlerClient).queryWithImportEvents()
      /home/smoyer1/git/git-bug/bridge/github/client.go:73 +0x1e5
  github.com/MichaelMure/git-bug/bridge/github.(*importMediator).queryIssue()
      /home/smoyer1/git/git-bug/bridge/github/import_mediator.go:316 +0x70d
  github.com/MichaelMure/git-bug/bridge/github.(*importMediator).fillImportEvents()
      /home/smoyer1/git/git-bug/bridge/github/import_mediator.go:149 +0x6e
  github.com/MichaelMure/git-bug/bridge/github.NewImportMediator.func1()
      /home/smoyer1/git/git-bug/bridge/github/import_mediator.go:91 +0x4c
==================
--- FAIL: TestGithubImporterIntegration (0.75s)
    testing.go:1312: race detected during execution of test
FAIL
FAIL    github.com/MichaelMure/git-bug/bridge/github    2.262s

Michael Muré (MichaelMure) commented 3 years ago (edited)

The first one was quite easy to track and fix (see https://github.com/MichaelMure/git-bug/pull/811), but the second one is going to be less easy.

The problem there it seems is that a channel is closed in a goroutine, while another is still has pending sends. This is apparently illegal in go and might be a sign of incorrect code structure. See https://github.com/golang/go/issues/30372#issuecomment-467107916 for some explanations.

Michael Muré (MichaelMure) commented 3 years ago

I think I got the other one with https://github.com/MichaelMure/git-bug/pull/813

Steve Moyer (smoyer64) commented 3 years ago (edited)

I've submitted #812 as a way to solve the race issue with the Github bridge (an alternate solution to your #813). Curiously, I had confused the two race conditions (first versus second in your comment above) and found the second easier to solve :)

Michael Muré (MichaelMure) commented 3 years ago

Solved with #811 and #813 :tada:

Michael Muré (MichaelMure) closed the bug 3 years ago

Timeline