Remove data race from zerolog provider

[ecordell]

It's important that With() on the adapter call With() on zerolog each time, so that we get a copy of the zerolog logger.

The zerolog logger isn't threadsafe by default

Here's an old test run showing the race:

https://github.com/authzed/spicedb/runs/5382249173?check_suite_focus=true

WARNING: DATA RACE
Write at 0x00c0008b0206 by goroutine 110:
  runtime.slicecopy()
      /opt/hostedtoolcache/go/1.17.7/x64/src/runtime/slice.go:284 +0x0
  github.com/rs/zerolog/internal/json.Encoder.AppendString()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.26.1/internal/json/string.go:61 +0x250
  github.com/rs/zerolog/internal/json.Encoder.AppendKey()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.26.1/internal/json/base.go:18 +0x304
  github.com/rs/zerolog.appendFieldList()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.26.1/fields.go:41 +0x20d
  github.com/rs/zerolog.appendFields()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.26.1/fields.go:31 +0x504
  github.com/rs/zerolog.Context.Fields()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.26.1/context.go:25 +0x25b
  github.com/grpc-ecosystem/go-grpc-middleware/providers/zerolog/v2.(*Logger).With()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/providers/zerolog/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/logger.go:52 +0x1f8
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.reportable.func1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/interceptors/logging/interceptors.go:96 +0xb12
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.CommonReportableFunc.ServerReporter()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/interceptors/reporter.go:85 +0x91
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.UnaryServerInterceptor.func1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/interceptors/server.go:19 +0x24c
  google.golang.org/grpc.chainUnaryInterceptors.func1.1()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1119 +0x226
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.UnaryServerInterceptor.func1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/interceptors/server.go:22 +0x2e3
  google.golang.org/grpc.chainUnaryInterceptors.func1.1()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1119 +0x226
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.UnaryServerInterceptor.func1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/interceptors/server.go:22 +0x2e3
  google.golang.org/grpc.chainUnaryInterceptors.func1.1()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1119 +0x226
  google.golang.org/grpc.chainUnaryInterceptors.func1()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1121 +0x285
  github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.3.0/chain.go:25 +0x8e
  github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.3.0/chain.go:34 +0x126
  github.com/authzed/spicedb/pkg/proto/dispatch/v1._DispatchService_DispatchLookup_Handler()
      /home/runner/work/spicedb/spicedb/pkg/proto/dispatch/v1/dispatch_grpc.pb.go:148 +0x1da
  github.com/authzed/grpcutil.WrapMethods.func1()
      /home/runner/go/pkg/mod/github.com/authzed/grpcutil@v0.0.0-20220104222419-f813f77722e5/middleware.go:67 +0x12e
  google.golang.org/grpc.(*Server).processUnaryRPC()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1282 +0x1514
  google.golang.org/grpc.(*Server).handleStream()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1616 +0xfd3
  google.golang.org/grpc.(*Server).serveStreams.func1.2()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:921 +0xfd

Previous write at 0x00c0008b0206 by goroutine 77:
  runtime.slicecopy()
      /opt/hostedtoolcache/go/1.17.7/x64/src/runtime/slice.go:284 +0x0
  github.com/rs/zerolog/internal/json.Encoder.AppendString()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.26.1/internal/json/string.go:61 +0x250
  github.com/rs/zerolog/internal/json.Encoder.AppendKey()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.26.1/internal/json/base.go:18 +0x304
  github.com/rs/zerolog.appendFieldList()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.26.1/fields.go:41 +0x20d
  github.com/rs/zerolog.appendFields()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.26.1/fields.go:31 +0x504
  github.com/rs/zerolog.Context.Fields()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.26.1/context.go:25 +0x25b
  github.com/grpc-ecosystem/go-grpc-middleware/providers/zerolog/v2.(*Logger).With()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/providers/zerolog/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/logger.go:52 +0x1f8
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.reportable.func1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/interceptors/logging/interceptors.go:96 +0xb12
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.CommonReportableFunc.ServerReporter()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/interceptors/reporter.go:85 +0x91
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.UnaryServerInterceptor.func1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/interceptors/server.go:19 +0x24c
  google.golang.org/grpc.chainUnaryInterceptors.func1.1()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1119 +0x226
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.UnaryServerInterceptor.func1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/interceptors/server.go:22 +0x2e3
  google.golang.org/grpc.chainUnaryInterceptors.func1.1()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1119 +0x226
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.UnaryServerInterceptor.func1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.0.0-rc.2.0.20210831071041-dd1540ef8252/interceptors/server.go:22 +0x2e3
  google.golang.org/grpc.chainUnaryInterceptors.func1.1()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1119 +0x226
  google.golang.org/grpc.chainUnaryInterceptors.func1()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1121 +0x285
  github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.3.0/chain.go:25 +0x8e
  github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1()
      /home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.3.0/chain.go:34 +0x126
  github.com/authzed/spicedb/pkg/proto/dispatch/v1._DispatchService_DispatchLookup_Handler()
      /home/runner/work/spicedb/spicedb/pkg/proto/dispatch/v1/dispatch_grpc.pb.go:148 +0x1da
  github.com/authzed/grpcutil.WrapMethods.func1()
      /home/runner/go/pkg/mod/github.com/authzed/grpcutil@v0.0.0-20220104222419-f813f77722e5/middleware.go:67 +0x12e
  google.golang.org/grpc.(*Server).processUnaryRPC()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1282 +0x1514
  google.golang.org/grpc.(*Server).handleStream()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:1616 +0xfd3
  google.golang.org/grpc.(*Server).serveStreams.func1.2()
      /home/runner/go/pkg/mod/google.golang.org/grpc@v1.44.0/server.go:921 +0xfd

And a newer run (using a local copy of the file in this PR):
https://github.com/authzed/spicedb/runs/5450521332?check_suite_focus=true

Open to discussing other options to address this, but this seemed the most straightforward.

[johanbrandhorst]

LGTM

[codecov-commenter]

Codecov Report

Merging #487 (c7c9d43) into v2 (6e2c2ac) will decrease coverage by 26.43%.
The diff coverage is 48.79%.

❗ Current head c7c9d43 differs from pull request most recent head 933d6a4. Consider uploading reports for the commit 933d6a4 to get more accurate results

@@             Coverage Diff             @@
##               v2     #487       +/-   ##
===========================================
- Coverage   84.01%   57.58%   -26.44%     
===========================================
  Files          30       28        -2     
  Lines         932     1530      +598     
===========================================
+ Hits          783      881       +98     
- Misses        110      586      +476     
- Partials       39       63       +24     

Impacted Files	Coverage Δ
chain.go	0.00% <ø> (-90.91%)	⬇️
interceptors/auth/auth.go	100.00% <ø> (ø)
interceptors/ratelimit/ratelimit.go	60.00% <0.00%> (-40.00%)	⬇️
interceptors/recovery/options.go	78.57% <ø> (ø)
metadata/single_key.go	60.00% <ø> (ø)
testing/testpb/interceptor_suite.go	0.00% <0.00%> (ø)
testing/testpb/test.manual_validator.pb.go	0.00% <0.00%> (ø)
util/backoffutils/backoff.go	60.00% <ø> (ø)
wrappers.go	66.66% <ø> (-33.34%)	⬇️
interceptors/reporter.go	45.45% <20.00%> (-17.05%)	⬇️
... and 22 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update a5b9e0b...933d6a4. Read the comment docs.

[johanbrandhorst]

Thanks for your contribution!

[johanbrandhorst]

Does this fix need to be ported to the v2 branch?

[matino]

@johanbrandhorst we can see this bug present in 2.0-rc2, it would be great to release rc3 :)

[johanbrandhorst]

Thanks for confirming this @matino. Would you be interested in porting this to v2? Or @ecordell?

[matino]

@johanbrandhorst I think it's already merged into v2 (https://github.com/grpc-ecosystem/go-grpc-middleware/commits/v2), do I miss something?

[johanbrandhorst]

Oh, I see, you simply want another release candidate? Maybe @bwplotka has some plans for a new release soon?