Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Settable grpc logger #402

Merged

Conversation

ptabor
Copy link
Contributor

@ptabor ptabor commented Mar 15, 2021

grpc_logsettable contains a thread-safe wrapper around grpc-logging infrastructure.

Go-grpc library assumes that logger can be only configured once as the SetLoggerV2 method is:
Not mutex-protected, should be called before any gRPC functions.

This provided package allows to supply parent logger once ("before any grpc"), but after change underlying implementation in thread-safe way when needed.

It's in particular useful for testing, where each testcase might need its own logger.

settable_test.go shows e2e usage of the enhanced infrastructure.


Case study:

In etcd we found it challenging to properly configure grpc logging in scope of the test framework.
When test fails we want to get all relevant logs from the test-case alone.

ZAP allows to wrap testing.T with zapttest.Logger. This needs to happen in each test-case.
When we try to use that zap-logger as grpc logger, we observe following RACEs:

ptab@ptab ~/corp/etcd% (cd tests && 'env' 'go' 'test' '-timeout=15m' '--race' 

'go.etcd.io/etcd/tests/v3/integration/clientv3/connectivity' --count=300 -run=TestBalancerUnderNetworkPartitionWatchLeader)
==================
WARNING: DATA RACE
Write at 0x000001ed49c0 by goroutine 42:
  google.golang.org/grpc/grpclog.SetLoggerV2()
      /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.32.0/grpclog/loggerv2.go:73 +0x23b
  github.com/grpc-ecosystem/go-grpc-middleware/logging/zap.ReplaceGrpcLoggerV2WithVerbosity()
      /home/ptab/private/golang/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.2.2/logging/zap/grpclogger.go:60 +0x1f6
  github.com/grpc-ecosystem/go-grpc-middleware/logging/zap.ReplaceGrpcLoggerV2()
      /home/ptab/private/golang/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.2.2/logging/zap/grpclogger.go:51 +0x11e
  go.etcd.io/etcd/tests/v3/integration.NewClusterV3()
      /home/ptab/corp/etcd/tests/integration/cluster.go:1282 +0xb5
  go.etcd.io/etcd/tests/v3/integration/clientv3/connectivity_test.testBalancerUnderNetworkPartitionWatch()
      /home/ptab/corp/etcd/tests/integration/clientv3/connectivity/network_partition_test.go:218 +0x135
  go.etcd.io/etcd/tests/v3/integration/clientv3/connectivity_test.TestBalancerUnderNetworkPartitionWatchLeader()
      /home/ptab/corp/etcd/tests/integration/clientv3/connectivity/network_partition_test.go:206 +0x3d
  testing.tRunner()
      /usr/lib/google-golang/src/testing/testing.go:1194 +0x202

Previous read at 0x000001ed49c0 by goroutine 304:
  [failed to restore the stack]

Goroutine 42 (running) created at:
  testing.(*T).Run()
      /usr/lib/google-golang/src/testing/testing.go:1239 +0x5d7
  testing.runTests.func1()
      /usr/lib/google-golang/src/testing/testing.go:1514 +0xa6
  testing.tRunner()
      /usr/lib/google-golang/src/testing/testing.go:1194 +0x202
  testing.runTests()
      /usr/lib/google-golang/src/testing/testing.go:1512 +0x612
  testing.(*M).Run()
      /usr/lib/google-golang/src/testing/testing.go:1420 +0x3c4
  go.etcd.io/etcd/pkg/v3/testutil.MustTestMainWithLeakDetection()
      /home/ptab/corp/etcd/pkg/testutil/leak.go:171 +0x38
  go.etcd.io/etcd/tests/v3/integration/clientv3/connectivity.TestMain()
      /home/ptab/corp/etcd/tests/integration/clientv3/connectivity/main_test.go:14 +0x272
  main.main()
      _testmain.go:109 +0x269

Goroutine 304 (finished) created at:
  google.golang.org/grpc/internal/transport.newHTTP2Server()
      /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.32.0/internal/transport/http2_server.go:288 +0x1904
  google.golang.org/grpc/internal/transport.NewServerTransport()
      /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.32.0/internal/transport/transport.go:537 +0x2f5
  google.golang.org/grpc.(*Server).newHTTP2Transport()
      /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.32.0/server.go:825 +0x2ca
  google.golang.org/grpc.(*Server).handleRawConn()
      /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.32.0/server.go:792 +0x684
  google.golang.org/grpc.(*Server).Serve.func3()
      /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.32.0/server.go:762 +0x4c
==================

The fact that server is property shutdown (GracefulStop + Stop), does not mitigate the reality that there is no synchronization between the connection goroutines and the next test-case start in terms of 'logger' memory.

The supplied implementation allows to configure it 'properly', on the cost of additional layer of indirection in the tests only.

@ptabor ptabor force-pushed the 20210315-settable-logger branch 3 times, most recently from 22818d0 to 7fc9235 Compare March 15, 2021 19:35
Copy link
Collaborator

@johanbrandhorst johanbrandhorst left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Minor comment on the docs license header, but generally this LGTM. Could you add a section to the README as well? We're also in the process of moving to v2, so if you want you may consider cherry picking this against v2 as well (some of the interfaces have changed though).

logging/settable/doc.go Outdated Show resolved Hide resolved
The go-grpc assumes that logger can be only configured once as the `SetLoggerV2`
method is:
```Not mutex-protected, should be called before any gRPC functions.``

This is insufficient in case of e.g. "testing" scenarios where
loggers might need to be supplied on per-test-case basis.
The settable_test.go is a good example of integration of
testing harness with grpclogging using zaptest,
that is canonical usecase for this infrastructure.
@codecov-io
Copy link

codecov-io commented Mar 16, 2021

Codecov Report

Merging #402 (91bfafe) into master (be4c235) will decrease coverage by 0.32%.
The diff coverage is 58.62%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #402      +/-   ##
==========================================
- Coverage   73.64%   73.31%   -0.33%     
==========================================
  Files          41       42       +1     
  Lines        1324     1353      +29     
==========================================
+ Hits          975      992      +17     
- Misses        295      307      +12     
  Partials       54       54              
Impacted Files Coverage Δ
logging/settable/logsettable.go 50.00% <50.00%> (ø)
logging/zap/grpclogger.go 41.93% <100.00%> (+11.16%) ⬆️

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 be4c235...91bfafe. Read the comment docs.

@johanbrandhorst johanbrandhorst merged commit a77ba4d into grpc-ecosystem:master Mar 16, 2021
@johanbrandhorst
Copy link
Collaborator

Thanks for your contribution! Could you please cherry pick this to the v2 branch? I'm not sure how many changes will be required though.

@ptabor
Copy link
Contributor Author

ptabor commented Mar 16, 2021

PTAL.

From quick glance, v2 is completely missing functionality of setting loggers as default grpc implementation grpclog.SetLoggerV2. Not sure if its intended, or still on the todo list.

@johanbrandhorst
Copy link
Collaborator

Yeah we might've removed it, it's been a while since I looked at it TBH.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants