v2: Race condition in logging interceptor test

[johanbrandhorst]

While merging an unrelated fix we had a test failure:

https://github.com/grpc-ecosystem/go-grpc-middleware/pull/318/checks?check_run_id=877450083

The relevant part is this:

2020-07-16T11:56:27.0723162Z === RUN   TestPayloadSuite/TestPing_LogsBothRequestAndResponse
2020-07-16T11:56:27.0723277Z ==================
2020-07-16T11:56:27.0723533Z WARNING: DATA RACE
2020-07-16T11:56:27.0723640Z Read at 0x00c000402bc0 by goroutine 12:
2020-07-16T11:56:27.0724126Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging_test.(*baseLoggingSuite).SetupTest()
2020-07-16T11:56:27.0724600Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/interceptors/logging/interceptors_test.go:141 +0xd1
2020-07-16T11:56:27.0724934Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging_test.(*loggingPayloadSuite).SetupTest()
2020-07-16T11:56:27.0725124Z       <autogenerated>:1 +0x59
2020-07-16T11:56:27.0725237Z   github.com/stretchr/testify/suite.Run.func2()
2020-07-16T11:56:27.0725471Z       /home/runner/go/pkg/mod/github.com/stretchr/testify@v1.4.0/suite/suite.go:119 +0x5e1
2020-07-16T11:56:27.0725607Z   testing.tRunner()
2020-07-16T11:56:27.0725764Z       /opt/hostedtoolcache/go/1.14.4/x64/src/testing/testing.go:991 +0x1eb
2020-07-16T11:56:27.0725834Z 
2020-07-16T11:56:27.0726118Z Previous write at 0x00c000402bc0 by goroutine 96:
2020-07-16T11:56:27.0726452Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging_test.(*baseMockLogger).Add()
2020-07-16T11:56:27.0726853Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/interceptors/logging/interceptors_test.go:101 +0x15b
2020-07-16T11:56:27.0727169Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging_test.(*mockLogger).Log()
2020-07-16T11:56:27.0727552Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/interceptors/logging/interceptors_test.go:126 +0x28b
2020-07-16T11:56:27.0727848Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.logProtoMessageAsJson()
2020-07-16T11:56:27.0728232Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/interceptors/logging/payload.go:138 +0x1e5
2020-07-16T11:56:27.0728565Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.(*serverPayloadReporter).PostMsgSend()
2020-07-16T11:56:27.0728940Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/interceptors/logging/payload.go:36 +0x2b0
2020-07-16T11:56:27.0729740Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.(*monitoredServerStream).SendMsg()
2020-07-16T11:56:27.0730140Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/interceptors/server.go:65 +0x12b
2020-07-16T11:56:27.0730450Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/grpctesting/testpb.(*testServicePingStreamServer).Send()
2020-07-16T11:56:27.0730797Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/grpctesting/testpb/test.pb.go:436 +0x6a
2020-07-16T11:56:27.0731092Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/grpctesting.(*TestPingService).PingStream()
2020-07-16T11:56:27.0731562Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/grpctesting/pingservice.go:69 +0x187
2020-07-16T11:56:27.0731869Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/grpctesting/testpb._TestService_PingStream_Handler()
2020-07-16T11:56:27.0732216Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/grpctesting/testpb/test.pb.go:422 +0xcd
2020-07-16T11:56:27.0732501Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.StreamServerInterceptor.func1()
2020-07-16T11:56:27.0732840Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/interceptors/server.go:35 +0x30e
2020-07-16T11:56:27.0733121Z   github.com/grpc-ecosystem/go-grpc-middleware/v2.ChainStreamServer.func1.1.1()
2020-07-16T11:56:27.0733438Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/chain.go:51 +0x7a
2020-07-16T11:56:27.0733726Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.StreamServerInterceptor.func1()
2020-07-16T11:56:27.0734074Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/interceptors/server.go:35 +0x30e
2020-07-16T11:56:27.0734349Z   github.com/grpc-ecosystem/go-grpc-middleware/v2.ChainStreamServer.func1.1.1()
2020-07-16T11:56:27.0734841Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/chain.go:51 +0x7a
2020-07-16T11:56:27.0735352Z   github.com/grpc-ecosystem/go-grpc-middleware/v2.ChainStreamServer.func1()
2020-07-16T11:56:27.0735693Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/chain.go:60 +0x135
2020-07-16T11:56:27.0735814Z   google.golang.org/grpc.(*Server).processStreamingRPC()
2020-07-16T11:56:27.0736006Z       /home/runner/go/pkg/mod/google.golang.org/grpc@v1.19.0/server.go:1182 +0xb25
2020-07-16T11:56:27.0736146Z   google.golang.org/grpc.(*Server).handleStream()
2020-07-16T11:56:27.0736325Z       /home/runner/go/pkg/mod/google.golang.org/grpc@v1.19.0/server.go:1254 +0x12bf
2020-07-16T11:56:27.0736466Z   google.golang.org/grpc.(*Server).serveStreams.func1.1()
2020-07-16T11:56:27.0736651Z       /home/runner/go/pkg/mod/google.golang.org/grpc@v1.19.0/server.go:690 +0xd8
2020-07-16T11:56:27.0757200Z 
2020-07-16T11:56:27.0757338Z Goroutine 12 (running) created at:
2020-07-16T11:56:27.0757449Z   testing.(*T).Run()
2020-07-16T11:56:27.0757842Z       /opt/hostedtoolcache/go/1.14.4/x64/src/testing/testing.go:1042 +0x660
2020-07-16T11:56:27.0757970Z   github.com/stretchr/testify/suite.runTests()
2020-07-16T11:56:27.0758159Z       /home/runner/go/pkg/mod/github.com/stretchr/testify@v1.4.0/suite/suite.go:151 +0xe3
2020-07-16T11:56:27.0758288Z   github.com/stretchr/testify/suite.Run()
2020-07-16T11:56:27.0758455Z       /home/runner/go/pkg/mod/github.com/stretchr/testify@v1.4.0/suite/suite.go:138 +0x6af
2020-07-16T11:56:27.0758897Z   github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging_test.TestPayloadSuite()
2020-07-16T11:56:27.0759279Z       /home/runner/work/go-grpc-middleware/go-grpc-middleware/interceptors/logging/payload_test.go:57 +0xbdc
2020-07-16T11:56:27.0759414Z   testing.tRunner()
2020-07-16T11:56:27.0759566Z       /opt/hostedtoolcache/go/1.14.4/x64/src/testing/testing.go:991 +0x1eb
2020-07-16T11:56:27.0759648Z 
2020-07-16T11:56:27.0759749Z Goroutine 96 (finished) created at:
2020-07-16T11:56:27.0759846Z   google.golang.org/grpc.(*Server).serveStreams.func1()
2020-07-16T11:56:27.0760013Z       /home/runner/go/pkg/mod/google.golang.org/grpc@v1.19.0/server.go:688 +0xb8
2020-07-16T11:56:27.0760309Z   google.golang.org/grpc/internal/transport.(*http2Server).operateHeaders()
2020-07-16T11:56:27.0760531Z       /home/runner/go/pkg/mod/google.golang.org/grpc@v1.19.0/internal/transport/http2_server.go:419 +0x14e0
2020-07-16T11:56:27.0760667Z   google.golang.org/grpc/internal/transport.(*http2Server).HandleStreams()
2020-07-16T11:56:27.0760855Z       /home/runner/go/pkg/mod/google.golang.org/grpc@v1.19.0/internal/transport/http2_server.go:459 +0x31e
2020-07-16T11:56:27.0760986Z   google.golang.org/grpc.(*Server).serveStreams()
2020-07-16T11:56:27.0761288Z       /home/runner/go/pkg/mod/google.golang.org/grpc@v1.19.0/server.go:686 +0x1b5
2020-07-16T11:56:27.0761416Z   google.golang.org/grpc.(*Server).handleRawConn.func1()
2020-07-16T11:56:27.0764586Z       /home/runner/go/pkg/mod/google.golang.org/grpc@v1.19.0/server.go:648 +0x50
2020-07-16T11:56:27.0764740Z ==================
2020-07-16T11:56:27.0764873Z     TestPayloadSuite/TestPing_LogsBothRequestAndResponse: testing.go:906: race detected during execution of test
2020-07-16T11:56:27.0765028Z     TestPayloadSuite: interceptor_suite.go:149: stopped grpc.Server at: 127.0.0.1:43289
2020-07-16T11:56:27.0765167Z     TestPayloadSuite: testing.go:906: race detected during execution of test
2020-07-16T11:56:27.0765551Z --- FAIL: TestPayloadSuite (0.06s)
2020-07-16T11:56:27.0765821Z     --- PASS: TestPayloadSuite/TestPingError_LogsOnlyRequestsOnError (0.00s)
2020-07-16T11:56:27.0766094Z     --- FAIL: TestPayloadSuite/TestPingStream_LogsAllRequestsAndResponses (0.02s)
2020-07-16T11:56:27.0766373Z     --- FAIL: TestPayloadSuite/TestPing_LogsBothRequestAndResponse (0.00s)
2020-07-16T11:56:27.0766500Z     : testing.go:906: race detected during execution of test
2020-07-16T11:56:27.0766593Z FAIL
2020-07-16T11:56:27.0766911Z FAIL	github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging	0.209s

May need a lock on the mock logger.

[johanbrandhorst]

Happened again https://pipelines.actions.githubusercontent.com/qcTmm8qsNot5sfW3WOK59juTlccgJLHrpBQud37vljvSUZ4TrZ/_apis/pipelines/1/runs/91/signedlogcontent/9?urlExpires=2020-09-08T13%3A03%3A15.8549828Z&urlSigningMethod=HMACV1&urlSignature=AFuElzGcw9aspqe0DpZs5WDmXRVTZ2kU3htXq14WqSQ%3D

[bwplotka]

Action Item:

• Replace time based tests with something mocked.

[yashrsharma44]

I think this issue has been fixed by #354.
Let me know if this issue re-appears, I will open it again.

[bwplotka]

💪

[chancez]

I'm seeing a similar race when using a logrus interceptor logger with v2 still. Here's an example stack trace. I'll try to make a small reproduction if possible though.

WARNING: DATA RACE
Read at 0x00c000425e40 by goroutine 309:
  github.com/sirupsen/logrus.(*Entry).WithFields()
      /home/runner/work/my-project/my-project/vendor/github.com/sirupsen/logrus/entry.go:150 +0x691
  github.com/example/my-project/internal/server.logrusInterceptorLogger.func1()
      /home/runner/work/my-project/my-project/internal/server/log.go:21 +0x501
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.LoggerFunc.Log()
      /home/runner/work/my-project/my-project/vendor/github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging/logging.go:173 +0x9c
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.(*reporter).PostMsgReceive()
      /home/runner/work/my-project/my-project/vendor/github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging/interceptors.go:100 +0x4ee
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.UnaryServerInterceptor.func1()
      /home/runner/work/my-project/my-project/vendor/github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/server.go:21 +0x2cb
  google.golang.org/grpc.getChainUnaryHandler.func1()
      /home/runner/work/my-project/my-project/vendor/google.golang.org/grpc/server.go:1156 +0x131
  github.com/example/my-project/internal/db/query.UnaryServerInterceptor.func1()
      /home/runner/work/my-project/my-project/internal/db/query/query.go:188 +0xd1
  google.golang.org/grpc.chainUnaryInterceptors.func1()
      /home/runner/work/my-project/my-project/vendor/google.golang.org/grpc/server.go:1147 +0xe2
  github.com/example/my-project/api/example-api/v1._ContainerService_GetProcessAncestors_Handler()
      /home/runner/work/my-project/my-project/vendor/github.com/example/my-project/api/example-api/v1/container_grpc.pb.go:206 +0x1dd
  google.golang.org/grpc.(*Server).processUnaryRPC()
      /home/runner/work/my-project/my-project/vendor/google.golang.org/grpc/server.go:1337 +0x17be
  google.golang.org/grpc.(*Server).handleStream()
      /home/runner/work/my-project/my-project/vendor/google.golang.org/grpc/server.go:1714 +0xff8
  google.golang.org/grpc.(*Server).serveStreams.func1.1()
      /home/runner/work/my-project/my-project/vendor/google.golang.org/grpc/server.go:959 +0xec

Previous write at 0x00c000425e40 by goroutine 306:
  github.com/sirupsen/logrus.(*Entry).WithFields()
      /home/runner/work/my-project/my-project/vendor/github.com/sirupsen/logrus/entry.go:150 +0x6d0
  github.com/example/my-project/internal/server.logrusInterceptorLogger.func1()
      /home/runner/work/my-project/my-project/internal/server/log.go:21 +0x501
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.LoggerFunc.Log()
      /home/runner/work/my-project/my-project/vendor/github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging/logging.go:173 +0x9c
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.(*reporter).PostCall()
      /home/runner/work/my-project/my-project/vendor/github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging/interceptors.go:44 +0x572
  github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors.StreamServerInterceptor.func1()
      /home/runner/work/my-project/my-project/vendor/github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/server.go:36 +0x3d7
  google.golang.org/grpc.getChainStreamHandler.func1()
      /home/runner/work/my-project/my-project/vendor/google.golang.org/grpc/server.go:1483 +0x12b
  github.com/example/my-project/internal/db/query.streamServerInterceptor()
      /home/runner/work/my-project/my-project/internal/db/query/query.go:222 +0x12f
  github.com/example/my-project/internal/db/query.StreamServerInterceptor.func1()
      /home/runner/work/my-project/my-project/internal/db/query/query.go:210 +0x8f
  google.golang.org/grpc.chainStreamInterceptors.func1()
      /home/runner/work/my-project/my-project/vendor/google.golang.org/grpc/server.go:1474 +0xd5
  google.golang.org/grpc.(*Server).processStreamingRPC()
      /home/runner/work/my-project/my-project/vendor/google.golang.org/grpc/server.go:1638 +0x1f9c
  google.golang.org/grpc.(*Server).handleStream()
      /home/runner/work/my-project/my-project/vendor/google.golang.org/grpc/server.go:1718 +0xfae
  google.golang.org/grpc.(*Server).serveStreams.func1.1()
      /home/runner/work/my-project/my-project/vendor/google.golang.org/grpc/server.go:959 +0xec

[chancez]

Turns out it was fixed by a18e1e2