race in TestDigestRollover

[vroldanbet]

WARNING: DATA RACE
Write at 0x00c000033450 by goroutine 57:
  github.com/authzed/spicedb/internal/datastore/proxy.TestDigestRollover()
      /home/runner/work/spicedb/spicedb/internal/datastore/proxy/hedging_test.go:221 +0x92b
  testing.tRunner()
      /opt/hostedtoolcache/go/1.18.1/x64/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/hostedtoolcache/go/1.18.1/x64/src/testing/testing.go:1486 +0x47

Previous read at 0x00c000033450 by goroutine 66:
  github.com/stretchr/testify/mock.(*Mock).findExpectedCall()
      /home/runner/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:293 +0x54
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /home/runner/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:401 +0xb9
  github.com/stretchr/testify/mock.(*Mock).Called()
      /home/runner/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:391 +0x1a4
  github.com/authzed/spicedb/internal/datastore/test.(*MockedDatastore).HeadRevision()
      /home/runner/work/spicedb/spicedb/internal/datastore/test/mock.go:51 +0xdb
  github.com/authzed/spicedb/internal/datastore/proxy.hedgingProxy.HeadRevision.func1()
      /home/runner/work/spicedb/spicedb/internal/datastore/proxy/hedging.go:199 +0x8d
  github.com/authzed/spicedb/internal/datastore/proxy.newHedger.func1.2()
      /home/runner/work/spicedb/spicedb/internal/datastore/proxy/hedging.go:91 +0x66

Goroutine 57 (running) created at:
  testing.(*T).Run()
      /opt/hostedtoolcache/go/1.18.1/x64/src/testing/testing.go:1486 +0x724
  testing.runTests.func1()
      /opt/hostedtoolcache/go/1.18.1/x64/src/testing/testing.go:1839 +0x99
  testing.tRunner()
      /opt/hostedtoolcache/go/1.18.1/x64/src/testing/testing.go:1439 +0x213
  testing.runTests()
      /opt/hostedtoolcache/go/1.18.1/x64/src/testing/testing.go:1837 +0x7e4
  testing.(*M).Run()
      /opt/hostedtoolcache/go/1.18.1/x64/src/testing/testing.go:1719 +0xa71
  main.main()
      _testmain.go:81 +0x2e4

Goroutine 66 (running) created at:
  github.com/authzed/spicedb/internal/datastore/proxy.newHedger.func1()
      /home/runner/work/spicedb/spicedb/internal/datastore/proxy/hedging.go:91 +0x58b
  github.com/authzed/spicedb/internal/datastore/proxy.hedgingProxy.HeadRevision()
      /home/runner/work/spicedb/spicedb/internal/datastore/proxy/hedging.go:207 +0x206
  github.com/authzed/spicedb/internal/datastore/proxy.TestDigestRollover()
      /home/runner/work/spicedb/spicedb/internal/datastore/proxy/hedging_test.go:216 +0x8aa
  testing.tRunner()
      /opt/hostedtoolcache/go/1.18.1/x64/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/hostedtoolcache/go/1.18.1/x64/src/testing/testing.go:1486 +0x47
==================
--- FAIL: TestDigestRollover (1.00s)
    hedging_test.go: PASS:	HeadRevision(string)
    hedging_test.go:240: PASS:	HeadRevision(string)
    hedging_test.go:240: PASS:	HeadRevision(string)
    testing.go:1312: race detected during execution of test
FAIL

[ecordell]

I see how this test-only race could happen (we're modifying the mocks that get used in goroutines spawned by the hedger), but I can't actually reproduce the race detector error.

What revision of spicedb do you see this on and in what environments? I tried on mac arm, go 1.18.1 with -race -test.count=100 and didn't see it.

[ecordell]

I let the test run in a loop in the background and hit a different issue:

=== RUN   TestDigestRollover
    hedging_test.go:201: PASS:	HeadRevision(string)
panic: 
assert: mock: The method has been called over 1 times.
	Either do one more Mock.On("HeadRevision").Return(...), or remove extra call.
	This call was unexpected:
		HeadRevision(*context.cancelCtx)
		0: &context.cancelCtx{Context:(*context.emptyCtx)(0xc0001a8018), mu:sync.Mutex{state:0, sema:0x0}, done:atomic.Value{v:interface {}(nil)}, children:map[context.canceler]struct {}(nil), err:error(nil)}
	at: [mock.go:51 hedging.go:199 asm_arm64.s:1259]

goroutine 157655 [running]:
github.com/stretchr/testify/mock.(*Mock).fail(0xc000a92aa0, {0x104c80660, 0xa5}, {0xc000f1ca00, 0x4, 0x4})
	/Users/evan/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:262 +0x140
github.com/stretchr/testify/mock.(*Mock).MethodCalled(0xc000a92aa0, {0x1050ca49e, 0xc}, {0xc000b90f40, 0x1, 0x1})
	/Users/evan/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:407 +0x264
github.com/stretchr/testify/mock.(*Mock).Called(0x0?, {0xc000b90f40, 0x1, 0x1})
	/Users/evan/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:391 +0x144
github.com/authzed/spicedb/internal/datastore/test.(*MockedDatastore).HeadRevision(0xc000a92aa0, {0x104f8d4b8?, 0xc000f1c640})
	/Users/evan/git/authzed/internal/spicedb/internal/datastore/test/mock.go:51 +0xc0
github.com/authzed/spicedb/internal/datastore/proxy.hedgingProxy.HeadRevision.func1({0x104f8d4b8, 0xc000f1c640}, 0x0?)
	/Users/evan/git/authzed/internal/spicedb/internal/datastore/proxy/hedging.go:199 +0x6c
created by github.com/authzed/spicedb/internal/datastore/proxy.newHedger.func1
	/Users/evan/git/authzed/internal/spicedb/internal/datastore/proxy/hedging.go:78 +0x24c

[josephschorr]

Unable to reproduce under stress testing. Closing and will reopen if encountered