[FAB-2734] Make gRPC logging configurable

The gRPC library has built in logging but
does not support leveled logging.  The logging
can be very noisy (e.g. when trying to connect to
a remote endpoint which is down) but also very
useful (e.g. for TLS errors).

The gossip component currently effectively disables
the gRPC logs which makes it difficult to debug.

This change adds the ability to turn gRPC logging
on or off.  The implementation is as follows:

- implement a custom logger which wraps calls to
flogging and uses module name "grpc"

- only logs at the debug level (except for fatal
log messages)

- explicit configuration provided in core.yaml
using logging.grpc inline with other modules

Change-Id: I78af0fbb6aed2bfb2ed1e6713c7e966d8d21b60c
Signed-off-by: Gari Singh <gari.r.singh@gmail.com>

common/flogging/grpclogger.go

@@ -0,0 +1,61 @@
+/*
+Copyright IBM Corp. 2017 All Rights Reserved.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+		 http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package flogging
+
+import (
+	"github.com/op/go-logging"
+	"google.golang.org/grpc/grpclog"
+)
+
+const GRPCModuleID = "grpc"
+
+func initgrpclogger() {
+	glogger := MustGetLogger(GRPCModuleID)
+	grpclog.SetLogger(&grpclogger{glogger})
+}
+
+// grpclogger implements the standard Go logging interface and wraps the
+// logger provided by the flogging package.  This is required in order to
+// replace the default log used by the grpclog package.
+type grpclogger struct {
+	logger *logging.Logger
+}
+
+func (g *grpclogger) Fatal(args ...interface{}) {
+	g.logger.Fatal(args...)
+}
+
+func (g *grpclogger) Fatalf(format string, args ...interface{}) {
+	g.logger.Fatalf(format, args...)
+}
+
+func (g *grpclogger) Fatalln(args ...interface{}) {
+	g.logger.Fatal(args...)
+}
+
+// NOTE: grpclog does not support leveled logs so for now use DEBUG
+func (g *grpclogger) Print(args ...interface{}) {
+	g.logger.Debug(args...)
+}
+
+func (g *grpclogger) Printf(format string, args ...interface{}) {
+	g.logger.Debugf(format, args...)
+}
+
+func (g *grpclogger) Println(args ...interface{}) {
+	g.logger.Debug(args...)
+}

common/flogging/grpclogger_test.go

@@ -0,0 +1,72 @@
+/*
+Copyright IBM Corp. 2017 All Rights Reserved.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+		 http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package flogging
+
+import (
+	"testing"
+
+	"github.com/op/go-logging"
+	"github.com/stretchr/testify/assert"
+	"google.golang.org/grpc/grpclog"
+)
+
+// from go-logging memory_test.go
+func MemoryRecordN(b *logging.MemoryBackend, n int) *logging.Record {
+	node := b.Head()
+	for i := 0; i < n; i++ {
+		if node == nil {
+			break
+		}
+		node = node.Next()
+	}
+	if node == nil {
+		return nil
+	}
+	return node.Record
+}
+
+func TestGRPCLogger(t *testing.T) {
+	initgrpclogger()
+	backend := logging.NewMemoryBackend(3)
+	logging.SetBackend(backend)
+	logging.SetLevel(defaultLevel, "")
+	SetModuleLevel(GRPCModuleID, "DEBUG")
+	messages := []string{"print test", "printf test", "println test"}
+	grpclog.Print(messages[0])
+	grpclog.Printf(messages[1])
+	grpclog.Println(messages[2])
+
+	for i, message := range messages {
+		assert.Equal(t, message, MemoryRecordN(backend, i).Message())
+		t.Log(MemoryRecordN(backend, i).Message())
+	}
+
+	// now make sure there's no logging at a level other than DEBUG
+	SetModuleLevel(GRPCModuleID, "INFO")
+	messages2 := []string{"print test2", "printf test2", "println test2"}
+	grpclog.Print(messages2[0])
+	grpclog.Printf(messages2[1])
+	grpclog.Println(messages2[2])
+
+	// should still be messages not messages2
+	for i, message := range messages {
+		assert.Equal(t, message, MemoryRecordN(backend, i).Message())
+		t.Log(MemoryRecordN(backend, i).Message())
+	}
+	// reset flogging
+	Reset()
+}

common/flogging/logging.go

@@ -47,6 +47,7 @@ var (
 func init() {
 	logger = logging.MustGetLogger(pkgLogID)
 	Reset()
+	initgrpclogger()
 }
 
 // Reset sets to logging to the defaults defined in this package.

gossip/util/logging.go

@@ -17,13 +17,10 @@ limitations under the License.
 package util
 
 import (
-	"io/ioutil"
-	"log"
 	"sync"
 
 	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/op/go-logging"
-	"google.golang.org/grpc/grpclog"
 )
 
 // Module names for logger initialization.
@@ -45,10 +42,6 @@ var lock = sync.Mutex{}
 // defaultTestSpec is the default logging level for gossip tests
 var defaultTestSpec = "WARNING"
 
-func init() {
-	grpclog.SetLogger(log.New(ioutil.Discard, "", 0))
-}
-
 // GetLogger returns a logger for given gossip module and peerID
 func GetLogger(module string, peerID string) *logging.Logger {
 	if peerID != "" {

peer/node/start.go

@@ -274,7 +274,7 @@ func serve(args []string) error {
 
 	// set the logging level for specific modules defined via environment
 	// variables or core.yaml
-	overrideLogModules := []string{"msp", "gossip", "ledger", "cauthdsl", "policies"}
+	overrideLogModules := []string{"msp", "gossip", "ledger", "cauthdsl", "policies", "grpc"}
 	for _, module := range overrideLogModules {
 		err = common.SetLogLevelFromViper(module)
 		if err != nil {

sampleconfig/core.yaml

@@ -31,6 +31,7 @@ logging:
     ledger:     info
     msp:        warning
     policies:     warning
+    grpc:       error
 
     format: '%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}'