Use log severity and verbosity level (#1340)

 - All logs use 1 severity level instead of printf
 - All transport logs only go to verbose level 2+
 - The default logger only log errors and verbosity level 1
 - Add environment variable GRPC_GO_LOG_SEVERITY_LEVEL and GRPC_GO_LOG_VERBOSITY_LEVEL to set severity or verbosity levels for the default logger

Author: menghanl

balancer.go

@@ -157,7 +157,7 @@ type roundRobin struct {
 func (rr *roundRobin) watchAddrUpdates() error {
 	updates, err := rr.w.Next()
 	if err != nil {
-		grpclog.Printf("grpc: the naming watcher stops working due to %v.\n", err)
+		grpclog.Warningf("grpc: the naming watcher stops working due to %v.", err)
 		return err
 	}
 	rr.mu.Lock()
@@ -173,7 +173,7 @@ func (rr *roundRobin) watchAddrUpdates() error {
 			for _, v := range rr.addrs {
 				if addr == v.addr {
 					exist = true
-					grpclog.Println("grpc: The name resolver wanted to add an existing address: ", addr)
+					grpclog.Infoln("grpc: The name resolver wanted to add an existing address: ", addr)
 					break
 				}
 			}
@@ -190,7 +190,7 @@ func (rr *roundRobin) watchAddrUpdates() error {
 				}
 			}
 		default:
-			grpclog.Println("Unknown update.Op ", update.Op)
+			grpclog.Errorln("Unknown update.Op ", update.Op)
 		}
 	}
 	// Make a copy of rr.addrs and write it onto rr.addrCh so that gRPC internals gets notified.

clientconn.go

@@ -632,7 +632,7 @@ func (cc *ClientConn) resetAddrConn(addr Address, block bool, tearDownErr error)
 		// Start a goroutine connecting to the server asynchronously.
 		go func() {
 			if err := ac.resetTransport(false); err != nil {
-				grpclog.Printf("Failed to dial %s: %v; please retry.", ac.addr.Addr, err)
+				grpclog.Warningln("Failed to dial %s: %v; please retry.", ac.addr.Addr, err)
 				if err != errConnClosing {
 					// Keep this ac in cc.conns, to get the reason it's torn down.
 					ac.tearDown(err)
@@ -868,7 +868,7 @@ func (ac *addrConn) resetTransport(closeTransport bool) error {
 			if e, ok := err.(transport.ConnectionError); ok && !e.Temporary() {
 				return err
 			}
-			grpclog.Printf("grpc: addrConn.resetTransport failed to create client transport: %v; Reconnecting to %v", err, ac.addr)
+			grpclog.Warningf("grpc: addrConn.resetTransport failed to create client transport: %v; Reconnecting to %v", err, ac.addr)
 			ac.mu.Lock()
 			if ac.state == Shutdown {
 				// ac.tearDown(...) has been invoked.
@@ -973,7 +973,7 @@ func (ac *addrConn) transportMonitor() {
 				ac.mu.Lock()
 				ac.printf("transport exiting: %v", err)
 				ac.mu.Unlock()
-				grpclog.Printf("grpc: addrConn.transportMonitor exits due to: %v", err)
+				grpclog.Warningf("grpc: addrConn.transportMonitor exits due to: %v", err)
 				if err != errConnClosing {
 					// Keep this ac in cc.conns, to get the reason it's torn down.
 					ac.tearDown(err)

grpclb.go

@@ -137,7 +137,7 @@ type balancer struct {
 func (b *balancer) watchAddrUpdates(w naming.Watcher, ch chan []remoteBalancerInfo) error {
 	updates, err := w.Next()
 	if err != nil {
-		grpclog.Printf("grpclb: failed to get next addr update from watcher: %v", err)
+		grpclog.Warningf("grpclb: failed to get next addr update from watcher: %v", err)
 		return err
 	}
 	b.mu.Lock()
@@ -162,21 +162,21 @@ func (b *balancer) watchAddrUpdates(w naming.Watcher, ch chan []remoteBalancerIn
 			md, ok := update.Metadata.(*AddrMetadataGRPCLB)
 			if !ok {
 				// TODO: Revisit the handling here and may introduce some fallback mechanism.
-				grpclog.Printf("The name resolution contains unexpected metadata %v", update.Metadata)
+				grpclog.Errorf("The name resolution contains unexpected metadata %v", update.Metadata)
 				continue
 			}
 			switch md.AddrType {
 			case Backend:
 				// TODO: Revisit the handling here and may introduce some fallback mechanism.
-				grpclog.Printf("The name resolution does not give grpclb addresses")
+				grpclog.Errorf("The name resolution does not give grpclb addresses")
 				continue
 			case GRPCLB:
 				b.rbs = append(b.rbs, remoteBalancerInfo{
 					addr: update.Addr,
 					name: md.ServerName,
 				})
 			default:
-				grpclog.Printf("Received unknow address type %d", md.AddrType)
+				grpclog.Errorf("Received unknow address type %d", md.AddrType)
 				continue
 			}
 		case naming.Delete:
@@ -188,7 +188,7 @@ func (b *balancer) watchAddrUpdates(w naming.Watcher, ch chan []remoteBalancerIn
 				}
 			}
 		default:
-			grpclog.Println("Unknown update.Op ", update.Op)
+			grpclog.Errorf("Unknown update.Op %v", update.Op)
 		}
 	}
 	// TODO: Fall back to the basic round-robin load balancing if the resulting address is
@@ -299,7 +299,7 @@ func (b *balancer) sendLoadReport(s *balanceLoadClientStream, interval time.Dura
 				ClientStats: &stats,
 			},
 		}); err != nil {
-			grpclog.Printf("grpclb: failed to send load report: %v", err)
+			grpclog.Errorf("grpclb: failed to send load report: %v", err)
 			return
 		}
 	}
@@ -310,7 +310,7 @@ func (b *balancer) callRemoteBalancer(lbc *loadBalancerClient, seq int) (retry b
 	defer cancel()
 	stream, err := lbc.BalanceLoad(ctx)
 	if err != nil {
-		grpclog.Printf("grpclb: failed to perform RPC to the remote balancer %v", err)
+		grpclog.Errorf("grpclb: failed to perform RPC to the remote balancer %v", err)
 		return
 	}
 	b.mu.Lock()
@@ -327,25 +327,25 @@ func (b *balancer) callRemoteBalancer(lbc *loadBalancerClient, seq int) (retry b
 		},
 	}
 	if err := stream.Send(initReq); err != nil {
-		grpclog.Printf("grpclb: failed to send init request: %v", err)
+		grpclog.Errorf("grpclb: failed to send init request: %v", err)
 		// TODO: backoff on retry?
 		return true
 	}
 	reply, err := stream.Recv()
 	if err != nil {
-		grpclog.Printf("grpclb: failed to recv init response: %v", err)
+		grpclog.Errorf("grpclb: failed to recv init response: %v", err)
 		// TODO: backoff on retry?
 		return true
 	}
 	initResp := reply.GetInitialResponse()
 	if initResp == nil {
-		grpclog.Println("grpclb: reply from remote balancer did not include initial response.")
+		grpclog.Errorf("grpclb: reply from remote balancer did not include initial response.")
 		return
 	}
 	// TODO: Support delegation.
 	if initResp.LoadBalancerDelegate != "" {
 		// delegation
-		grpclog.Println("TODO: Delegation is not supported yet.")
+		grpclog.Errorf("TODO: Delegation is not supported yet.")
 		return
 	}
 	streamDone := make(chan struct{})
@@ -360,7 +360,7 @@ func (b *balancer) callRemoteBalancer(lbc *loadBalancerClient, seq int) (retry b
 	for {
 		reply, err := stream.Recv()
 		if err != nil {
-			grpclog.Printf("grpclb: failed to recv server list: %v", err)
+			grpclog.Errorf("grpclb: failed to recv server list: %v", err)
 			break
 		}
 		b.mu.Lock()
@@ -394,7 +394,7 @@ func (b *balancer) Start(target string, config BalancerConfig) error {
 	w, err := b.r.Resolve(target)
 	if err != nil {
 		b.mu.Unlock()
-		grpclog.Printf("grpclb: failed to resolve address: %v, err: %v", target, err)
+		grpclog.Errorf("grpclb: failed to resolve address: %v, err: %v", target, err)
 		return err
 	}
 	b.w = w
@@ -404,7 +404,7 @@ func (b *balancer) Start(target string, config BalancerConfig) error {
 	go func() {
 		for {
 			if err := b.watchAddrUpdates(w, balancerAddrsCh); err != nil {
-				grpclog.Printf("grpclb: the naming watcher stops working due to %v.\n", err)
+				grpclog.Warningf("grpclb: the naming watcher stops working due to %v.\n", err)
 				close(balancerAddrsCh)
 				return
 			}
@@ -495,7 +495,7 @@ func (b *balancer) Start(target string, config BalancerConfig) error {
 			if creds := config.DialCreds; creds != nil {
 				if rb.name != "" {
 					if err := creds.OverrideServerName(rb.name); err != nil {
-						grpclog.Printf("grpclb: failed to override the server name in the credentials: %v", err)
+						grpclog.Warningf("grpclb: failed to override the server name in the credentials: %v", err)
 						continue
 					}
 				}
@@ -510,7 +510,7 @@ func (b *balancer) Start(target string, config BalancerConfig) error {
 			ccError = make(chan struct{})
 			cc, err = Dial(rb.addr, dopts...)
 			if err != nil {
-				grpclog.Printf("grpclb: failed to setup a connection to the remote balancer %v: %v", rb.addr, err)
+				grpclog.Warningf("grpclb: failed to setup a connection to the remote balancer %v: %v", rb.addr, err)
 				close(ccError)
 				continue
 			}

grpclog/glogger/glogger.go

@@ -21,6 +21,8 @@
 package glogger
 
 import (
+	"fmt"
+
 	"github.com/golang/glog"
 	"google.golang.org/grpc/grpclog"
 )
@@ -32,51 +34,51 @@ func init() {
 type glogger struct{}
 
 func (g *glogger) Info(args ...interface{}) {
-	glog.Info(args...)
+	glog.InfoDepth(2, args...)
 }
 
 func (g *glogger) Infoln(args ...interface{}) {
-	glog.Infoln(args...)
+	glog.InfoDepth(2, fmt.Sprintln(args...))
 }
 
 func (g *glogger) Infof(format string, args ...interface{}) {
-	glog.Infof(format, args...)
+	glog.InfoDepth(2, fmt.Sprintf(format, args...))
 }
 
 func (g *glogger) Warning(args ...interface{}) {
-	glog.Warning(args...)
+	glog.WarningDepth(2, args...)
 }
 
 func (g *glogger) Warningln(args ...interface{}) {
-	glog.Warningln(args...)
+	glog.WarningDepth(2, fmt.Sprintln(args...))
 }
 
 func (g *glogger) Warningf(format string, args ...interface{}) {
-	glog.Warningf(format, args...)
+	glog.WarningDepth(2, fmt.Sprintf(format, args...))
 }
 
 func (g *glogger) Error(args ...interface{}) {
-	glog.Error(args...)
+	glog.ErrorDepth(2, args...)
 }
 
 func (g *glogger) Errorln(args ...interface{}) {
-	glog.Errorln(args...)
+	glog.ErrorDepth(2, fmt.Sprintln(args...))
 }
 
 func (g *glogger) Errorf(format string, args ...interface{}) {
-	glog.Errorf(format, args...)
+	glog.ErrorDepth(2, fmt.Sprintf(format, args...))
 }
 
 func (g *glogger) Fatal(args ...interface{}) {
-	glog.Fatal(args...)
+	glog.FatalDepth(2, args...)
 }
 
 func (g *glogger) Fatalln(args ...interface{}) {
-	glog.Fatalln(args...)
+	glog.FatalDepth(2, fmt.Sprintln(args...))
 }
 
 func (g *glogger) Fatalf(format string, args ...interface{}) {
-	glog.Fatalf(format, args...)
+	glog.FatalDepth(2, fmt.Sprintf(format, args...))
 }
 
 func (g *glogger) V(l int) bool {

grpclog/grpclog.go

@@ -31,7 +31,15 @@
  *
  */
 
-package grpclog
+// Package grpclog defines logging for grpc.
+//
+// All logs in transport package only go to verbose level 2.
+// All logs in other packages in grpc are logged in spite of the verbosity level.
+//
+// In the default logger,
+// severity level can be set by environment variable GRPC_GO_LOG_SEVERITY_LEVEL,
+// verbosity level can be set by GRPC_GO_LOG_VERBOSITY_LEVEL.
+package grpclog // import "google.golang.org/grpc/grpclog"
 
 import "os"
 

grpclog/logger.go

@@ -16,8 +16,7 @@
  *
  */
 
-// Package grpclog defines logging for grpc.
-package grpclog // import "google.golang.org/grpc/grpclog"
+package grpclog
 
 // Logger mimics golang's standard Logger as an interface.
 // Deprecated: use LoggerV2.

grpclog/loggerv2.go

@@ -31,16 +31,14 @@
  *
  */
 
-/*
-Package grpclog defines logging for grpc.
-*/
-package grpclog // import "google.golang.org/grpc/grpclog"
+package grpclog
 
 import (
 	"io"
 	"io/ioutil"
 	"log"
 	"os"
+	"strconv"
 )
 
 // LoggerV2 does underlying logging work for grpclog.
@@ -104,6 +102,7 @@ var severityName = []string{
 // loggerT is the default logger used by grpclog.
 type loggerT struct {
 	m []*log.Logger
+	v int
 }
 
 // NewLoggerV2 creates a loggerV2 with the provided writers.
@@ -112,19 +111,44 @@ type loggerT struct {
 // Warning logs will be written to warningW and infoW.
 // Info logs will be written to infoW.
 func NewLoggerV2(infoW, warningW, errorW io.Writer) LoggerV2 {
+	return NewLoggerV2WithVerbosity(infoW, warningW, errorW, 0)
+}
+
+// NewLoggerV2WithVerbosity creates a loggerV2 with the provided writers and
+// verbosity level.
+func NewLoggerV2WithVerbosity(infoW, warningW, errorW io.Writer, v int) LoggerV2 {
 	var m []*log.Logger
 	m = append(m, log.New(infoW, severityName[infoLog]+": ", log.LstdFlags))
 	m = append(m, log.New(io.MultiWriter(infoW, warningW), severityName[warningLog]+": ", log.LstdFlags))
 	ew := io.MultiWriter(infoW, warningW, errorW) // ew will be used for error and fatal.
 	m = append(m, log.New(ew, severityName[errorLog]+": ", log.LstdFlags))
 	m = append(m, log.New(ew, severityName[fatalLog]+": ", log.LstdFlags))
-	return &loggerT{m: m}
+	return &loggerT{m: m, v: v}
 }
 
 // newLoggerV2 creates a loggerV2 to be used as default logger.
 // All logs are written to stderr.
 func newLoggerV2() LoggerV2 {
-	return NewLoggerV2(os.Stderr, ioutil.Discard, ioutil.Discard)
+	errorW := ioutil.Discard
+	warningW := ioutil.Discard
+	infoW := ioutil.Discard
+
+	logLevel := os.Getenv("GRPC_GO_LOG_SEVERITY_LEVEL")
+	switch logLevel {
+	case "", "ERROR", "error": // If env is unset, set level to ERROR.
+		errorW = os.Stderr
+	case "WARNING", "warning":
+		warningW = os.Stderr
+	case "INFO", "info":
+		infoW = os.Stderr
+	}
+
+	var v int
+	vLevel := os.Getenv("GRPC_GO_LOG_VERBOSITY_LEVEL")
+	if vl, err := strconv.Atoi(vLevel); err == nil {
+		v = vl
+	}
+	return NewLoggerV2WithVerbosity(infoW, warningW, errorW, v)
 }
 
 func (g *loggerT) Info(args ...interface{}) {
@@ -176,7 +200,5 @@ func (g *loggerT) Fatalf(format string, args ...interface{}) {
 }
 
 func (g *loggerT) V(l int) bool {
-	// Returns true for all verbose level.
-	// TODO support verbose level in the default logger.
-	return true
+	return l <= g.v
 }