Settable grpc logger (#402)

* SettableLoggerV2 to dynamically change grpc logger.

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.

* Integrate ZAP with SettableLoggerV2.

The settable_test.go is a good example of integration of
testing harness with grpclogging using zaptest,
that is canonical usecase for this infrastructure.

Author: ptabor

README.md

@@ -59,6 +59,7 @@ myServer := grpc.NewServer(
    * [`grpc_zap`](logging/zap/) - integration of [zap](https://github.com/uber-go/zap) logging library into gRPC handlers.
    * [`grpc_logrus`](logging/logrus/) - integration of [logrus](https://github.com/sirupsen/logrus) logging library into gRPC handlers.
    * [`grpc_kit`](logging/kit/) - integration of [go-kit](https://github.com/go-kit/kit/tree/master/log) logging library into gRPC handlers.
+   * [`grpc_grpc_logsettable`](logging/settable/) - a wrapper around `grpclog.LoggerV2` that allows to replace loggers in runtime (thread-safe).
 
 #### Monitoring
    * [`grpc_prometheus`⚡](https://github.com/grpc-ecosystem/go-grpc-prometheus) - Prometheus client-side and server-side monitoring middleware

logging/doc.go

@@ -1,6 +1,3 @@
-// Copyright 2017 Michal Witkowski. All Rights Reserved.
-// See LICENSE for licensing terms.
-
 //
 /*
 grpc_logging is a "parent" package for gRPC logging middlewares.

logging/settable/doc.go

@@ -0,0 +1,16 @@
+//
+/*
+grpc_logsettable contains a thread-safe wrapper around grpc-logging
+infrastructure.
+
+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 package allows to supply parent logger once ("before any grpc"), but
+later change underlying implementation in thread-safe way when needed.
+
+It's in particular useful for testing, where each testcase might need its own
+logger.
+*/
+package grpc_logsettable

logging/settable/logsettable.go

@@ -0,0 +1,99 @@
+package grpc_logsettable
+
+import (
+	"io/ioutil"
+	"sync"
+
+	"google.golang.org/grpc/grpclog"
+)
+
+// SettableLoggerV2 is thread-safe.
+type SettableLoggerV2 interface {
+	grpclog.LoggerV2
+	// Sets given logger as the underlying implementation.
+	Set(loggerv2 grpclog.LoggerV2)
+	// Sets `discard` logger as the underlying implementation.
+	Reset()
+}
+
+// ReplaceGrpcLoggerV2 creates and configures SettableLoggerV2 as grpc logger.
+func ReplaceGrpcLoggerV2() SettableLoggerV2 {
+	settable := &settableLoggerV2{}
+	settable.Reset()
+	grpclog.SetLoggerV2(settable)
+	return settable
+}
+
+// SettableLoggerV2 implements SettableLoggerV2
+type settableLoggerV2 struct {
+	log grpclog.LoggerV2
+	mu  sync.RWMutex
+}
+
+func (s *settableLoggerV2) Set(log grpclog.LoggerV2) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	s.log = log
+}
+
+func (s *settableLoggerV2) Reset() {
+	s.Set(grpclog.NewLoggerV2(ioutil.Discard, ioutil.Discard, ioutil.Discard))
+}
+
+func (s *settableLoggerV2) get() grpclog.LoggerV2 {
+	s.mu.RLock()
+	defer s.mu.RUnlock()
+	return s.log
+}
+
+func (s *settableLoggerV2) Info(args ...interface{}) {
+	s.get().Info(args)
+}
+
+func (s *settableLoggerV2) Infoln(args ...interface{}) {
+	s.get().Infoln(args)
+}
+
+func (s *settableLoggerV2) Infof(format string, args ...interface{}) {
+	s.get().Infof(format, args)
+}
+
+func (s *settableLoggerV2) Warning(args ...interface{}) {
+	s.get().Warning(args)
+}
+
+func (s *settableLoggerV2) Warningln(args ...interface{}) {
+	s.get().Warningln(args)
+}
+
+func (s *settableLoggerV2) Warningf(format string, args ...interface{}) {
+	s.get().Warningf(format, args)
+}
+
+func (s *settableLoggerV2) Error(args ...interface{}) {
+	s.get().Error(args)
+}
+
+func (s *settableLoggerV2) Errorln(args ...interface{}) {
+	s.get().Errorln(args)
+}
+
+func (s *settableLoggerV2) Errorf(format string, args ...interface{}) {
+	s.get().Errorf(format, args)
+}
+
+func (s *settableLoggerV2) Fatal(args ...interface{}) {
+	s.get().Fatal(args)
+}
+
+func (s *settableLoggerV2) Fatalln(args ...interface{}) {
+	s.get().Fatalln(args)
+}
+
+func (s *settableLoggerV2) Fatalf(format string, args ...interface{}) {
+	s.get().Fatalf(format, args)
+}
+
+func (s *settableLoggerV2) V(l int) bool {
+	return s.get().V(l)
+}

logging/settable/logsettable_test.go

@@ -0,0 +1,48 @@
+package grpc_logsettable_test
+
+import (
+	"bytes"
+	"io/ioutil"
+	"os"
+	"testing"
+
+	grpc_logsettable "github.com/grpc-ecosystem/go-grpc-middleware/logging/settable"
+	"github.com/stretchr/testify/assert"
+	"google.golang.org/grpc/grpclog"
+)
+
+func ExampleSettableLoggerV2_init() {
+	l1 := grpclog.NewLoggerV2(ioutil.Discard, ioutil.Discard, ioutil.Discard)
+	l2 := grpclog.NewLoggerV2(os.Stdout, os.Stdout, os.Stdout)
+
+	settableLogger := grpc_logsettable.ReplaceGrpcLoggerV2()
+	grpclog.Info("Discarded by default")
+
+	settableLogger.Set(l1)
+	grpclog.Info("Discarded log by l1")
+
+	settableLogger.Set(l2)
+	grpclog.Info("Emitted log by l2")
+	// Expected output: INFO: 2021/03/15 12:59:54 [Emitted log by l2]
+}
+
+func TestSettableLoggerV2_init(t *testing.T) {
+	l1buffer := &bytes.Buffer{}
+	l1 := grpclog.NewLoggerV2(l1buffer, l1buffer, l1buffer)
+
+	l2buffer := &bytes.Buffer{}
+	l2 := grpclog.NewLoggerV2(l2buffer, l2buffer, l2buffer)
+
+	settableLogger := grpc_logsettable.ReplaceGrpcLoggerV2()
+	grpclog.Info("Discarded by default")
+
+	settableLogger.Set(l1)
+	grpclog.SetLoggerV2(settableLogger)
+	grpclog.Info("Emitted log by l1")
+
+	settableLogger.Set(l2)
+	grpclog.Info("Emitted log by l2")
+
+	assert.Contains(t, l1buffer.String(), "Emitted log by l1")
+	assert.Contains(t, l2buffer.String(), "Emitted log by l2")
+}

logging/zap/doc.go

@@ -70,5 +70,6 @@ Note - due to implementation ZAP differs from Logrus in the "grpc.request.conten
 
 
 Please see examples and tests for examples of use.
+Please see settable_test.go for canonical integration through "zaptest" with golang testing infrastructure.
 */
 package grpc_zap

logging/zap/grpclogger.go

@@ -6,6 +6,7 @@ package grpc_zap
 import (
 	"fmt"
 
+	grpc_logsettable "github.com/grpc-ecosystem/go-grpc-middleware/logging/settable"
 	"go.uber.org/zap"
 	"google.golang.org/grpc/grpclog"
 )
@@ -47,11 +48,13 @@ func (l *zapGrpcLogger) Println(args ...interface{}) {
 }
 
 // ReplaceGrpcLoggerV2 replaces the grpc_log.LoggerV2 with the provided logger.
+// It should be called before any gRPC functions.
 func ReplaceGrpcLoggerV2(logger *zap.Logger) {
 	ReplaceGrpcLoggerV2WithVerbosity(logger, 0)
 }
 
 // ReplaceGrpcLoggerV2WithVerbosity replaces the grpc_.LoggerV2 with the provided logger and verbosity.
+// It should be called before any gRPC functions.
 func ReplaceGrpcLoggerV2WithVerbosity(logger *zap.Logger, verbosity int) {
 	zgl := &zapGrpcLoggerV2{
 		logger:    logger.With(SystemField, zap.Bool("grpc_log", true)),
@@ -60,6 +63,22 @@ func ReplaceGrpcLoggerV2WithVerbosity(logger *zap.Logger, verbosity int) {
 	grpclog.SetLoggerV2(zgl)
 }
 
+// SetGrpcLoggerV2 replaces the grpc_log.LoggerV2 with the provided logger.
+// It can be used even when grpc infrastructure was initialized.
+func SetGrpcLoggerV2(settable grpc_logsettable.SettableLoggerV2, logger *zap.Logger) {
+	SetGrpcLoggerV2WithVerbosity(settable, logger, 0)
+}
+
+// SetGrpcLoggerV2WithVerbosity replaces the grpc_.LoggerV2 with the provided logger and verbosity.
+// It can be used even when grpc infrastructure was initialized.
+func SetGrpcLoggerV2WithVerbosity(settable grpc_logsettable.SettableLoggerV2, logger *zap.Logger, verbosity int) {
+	zgl := &zapGrpcLoggerV2{
+		logger:    logger.With(SystemField, zap.Bool("grpc_log", true)),
+		verbosity: verbosity,
+	}
+	settable.Set(zgl)
+}
+
 type zapGrpcLoggerV2 struct {
 	logger    *zap.Logger
 	verbosity int

logging/zap/settable_test.go

@@ -0,0 +1,33 @@
+package grpc_zap_test
+
+import (
+	"testing"
+
+	grpc_logsettable "github.com/grpc-ecosystem/go-grpc-middleware/logging/settable"
+	grpc_zap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap"
+	"go.uber.org/zap/zaptest"
+)
+
+var grpc_logger grpc_logsettable.SettableLoggerV2
+
+func init() {
+	grpc_logger = grpc_logsettable.ReplaceGrpcLoggerV2()
+}
+
+func beforeTest(t testing.TB) {
+	grpc_zap.SetGrpcLoggerV2(grpc_logger, zaptest.NewLogger(t))
+
+	// Starting from go-1.15+ automated 'reset' can also be set:
+	// t.Cleanup(func() {
+	//     grpc_logger.Reset()
+	// })
+}
+
+// This test illustrates setting up a testing harness that attributes
+// all grpc logs emitted during the test to the test-specific log.
+//
+// In case of test failure, only logs emitted by this testcase will be printed.
+func TestSpecificLogging(t *testing.T) {
+	beforeTest(t)
+	grpc_logger.Info("Test specific log-line")
+}