Implemented component logging (#3617)

balancer/base/balancer.go

@@ -28,6 +28,8 @@ import (
 	"google.golang.org/grpc/resolver"
 )
 
+var logger = grpclog.Component("balancer")
+
 type baseBuilder struct {
 	name          string
 	pickerBuilder PickerBuilder
@@ -91,8 +93,8 @@ func (b *baseBalancer) ResolverError(err error) {
 
 func (b *baseBalancer) UpdateClientConnState(s balancer.ClientConnState) error {
 	// TODO: handle s.ResolverState.ServiceConfig?
-	if grpclog.V(2) {
-		grpclog.Infoln("base.baseBalancer: got new ClientConn state: ", s)
+	if logger.V(2) {
+		logger.Info("base.baseBalancer: got new ClientConn state: ", s)
 	}
 	// Successful resolution; clear resolver error and ensure we return nil.
 	b.resolverErr = nil
@@ -104,7 +106,7 @@ func (b *baseBalancer) UpdateClientConnState(s balancer.ClientConnState) error {
 			// a is a new address (not existing in b.subConns).
 			sc, err := b.cc.NewSubConn([]resolver.Address{a}, balancer.NewSubConnOptions{HealthCheckEnabled: b.config.HealthCheck})
 			if err != nil {
-				grpclog.Warningf("base.baseBalancer: failed to create new SubConn: %v", err)
+				logger.Warningf("base.baseBalancer: failed to create new SubConn: %v", err)
 				continue
 			}
 			b.subConns[a] = sc
@@ -168,13 +170,13 @@ func (b *baseBalancer) regeneratePicker() {
 
 func (b *baseBalancer) UpdateSubConnState(sc balancer.SubConn, state balancer.SubConnState) {
 	s := state.ConnectivityState
-	if grpclog.V(2) {
-		grpclog.Infof("base.baseBalancer: handle SubConn state change: %p, %v", sc, s)
+	if logger.V(2) {
+		logger.Infof("base.baseBalancer: handle SubConn state change: %p, %v", sc, s)
 	}
 	oldS, ok := b.scStates[sc]
 	if !ok {
-		if grpclog.V(2) {
-			grpclog.Infof("base.baseBalancer: got state changes for an unknown SubConn: %p, %v", sc, s)
+		if logger.V(2) {
+			logger.Infof("base.baseBalancer: got state changes for an unknown SubConn: %p, %v", sc, s)
 		}
 		return
 	}

balancer/grpclb/grpclb.go

@@ -50,6 +50,7 @@ const (
 )
 
 var errServerTerminatedConnection = errors.New("grpclb: failed to recv server list: server terminated connection")
+var logger = grpclog.Component("grpclb")
 
 func convertDuration(d *durationpb.Duration) time.Duration {
 	if d == nil {
@@ -150,11 +151,11 @@ func (b *lbBuilder) Build(cc balancer.ClientConn, opt balancer.BuildOptions) bal
 	if opt.CredsBundle != nil {
 		lb.grpclbClientConnCreds, err = opt.CredsBundle.NewWithMode(internal.CredsBundleModeBalancer)
 		if err != nil {
-			grpclog.Warningf("lbBalancer: client connection creds NewWithMode failed: %v", err)
+			logger.Warningf("lbBalancer: client connection creds NewWithMode failed: %v", err)
 		}
 		lb.grpclbBackendCreds, err = opt.CredsBundle.NewWithMode(internal.CredsBundleModeBackendFromBalancer)
 		if err != nil {
-			grpclog.Warningf("lbBalancer: backend creds NewWithMode failed: %v", err)
+			logger.Warningf("lbBalancer: backend creds NewWithMode failed: %v", err)
 		}
 	}
 
@@ -310,16 +311,16 @@ func (lb *lbBalancer) aggregateSubConnStates() connectivity.State {
 
 func (lb *lbBalancer) UpdateSubConnState(sc balancer.SubConn, scs balancer.SubConnState) {
 	s := scs.ConnectivityState
-	if grpclog.V(2) {
-		grpclog.Infof("lbBalancer: handle SubConn state change: %p, %v", sc, s)
+	if logger.V(2) {
+		logger.Infof("lbBalancer: handle SubConn state change: %p, %v", sc, s)
 	}
 	lb.mu.Lock()
 	defer lb.mu.Unlock()
 
 	oldS, ok := lb.scStates[sc]
 	if !ok {
-		if grpclog.V(2) {
-			grpclog.Infof("lbBalancer: got state changes for an unknown SubConn: %p, %v", sc, s)
+		if logger.V(2) {
+			logger.Infof("lbBalancer: got state changes for an unknown SubConn: %p, %v", sc, s)
 		}
 		return
 	}
@@ -393,8 +394,8 @@ func (lb *lbBalancer) handleServiceConfig(gc *grpclbServiceConfig) {
 	if lb.usePickFirst == newUsePickFirst {
 		return
 	}
-	if grpclog.V(2) {
-		grpclog.Infof("lbBalancer: switching mode, new usePickFirst: %+v", newUsePickFirst)
+	if logger.V(2) {
+		logger.Infof("lbBalancer: switching mode, new usePickFirst: %+v", newUsePickFirst)
 	}
 	lb.refreshSubConns(lb.backendAddrs, lb.inFallback, newUsePickFirst)
 }
@@ -405,8 +406,8 @@ func (lb *lbBalancer) ResolverError(error) {
 }
 
 func (lb *lbBalancer) UpdateClientConnState(ccs balancer.ClientConnState) error {
-	if grpclog.V(2) {
-		grpclog.Infof("lbBalancer: UpdateClientConnState: %+v", ccs)
+	if logger.V(2) {
+		logger.Infof("lbBalancer: UpdateClientConnState: %+v", ccs)
 	}
 	gc, _ := ccs.BalancerConfig.(*grpclbServiceConfig)
 	lb.handleServiceConfig(gc)

balancer/grpclb/grpclb_remote_balancer.go

@@ -33,7 +33,6 @@ import (
 	"google.golang.org/grpc/balancer"
 	lbpb "google.golang.org/grpc/balancer/grpclb/grpc_lb_v1"
 	"google.golang.org/grpc/connectivity"
-	"google.golang.org/grpc/grpclog"
 	"google.golang.org/grpc/internal/backoff"
 	"google.golang.org/grpc/internal/channelz"
 	"google.golang.org/grpc/keepalive"
@@ -44,8 +43,8 @@ import (
 // processServerList updates balancer's internal state, create/remove SubConns
 // and regenerates picker using the received serverList.
 func (lb *lbBalancer) processServerList(l *lbpb.ServerList) {
-	if grpclog.V(2) {
-		grpclog.Infof("lbBalancer: processing server list: %+v", l)
+	if logger.V(2) {
+		logger.Infof("lbBalancer: processing server list: %+v", l)
 	}
 	lb.mu.Lock()
 	defer lb.mu.Unlock()
@@ -56,8 +55,8 @@ func (lb *lbBalancer) processServerList(l *lbpb.ServerList) {
 
 	// If the new server list == old server list, do nothing.
 	if cmp.Equal(lb.fullServerList, l.Servers, cmp.Comparer(proto.Equal)) {
-		if grpclog.V(2) {
-			grpclog.Infof("lbBalancer: new serverlist same as the previous one, ignoring")
+		if logger.V(2) {
+			logger.Infof("lbBalancer: new serverlist same as the previous one, ignoring")
 		}
 		return
 	}
@@ -81,8 +80,8 @@ func (lb *lbBalancer) processServerList(l *lbpb.ServerList) {
 			Addr:     fmt.Sprintf("%s:%d", ipStr, s.Port),
 			Metadata: &md,
 		}
-		if grpclog.V(2) {
-			grpclog.Infof("lbBalancer: server list entry[%d]: ipStr:|%s|, port:|%d|, load balancer token:|%v|",
+		if logger.V(2) {
+			logger.Infof("lbBalancer: server list entry[%d]: ipStr:|%s|, port:|%d|, load balancer token:|%v|",
 				i, ipStr, s.Port, s.LoadBalanceToken)
 		}
 		backendAddrs = append(backendAddrs, addr)
@@ -150,7 +149,7 @@ func (lb *lbBalancer) refreshSubConns(backendAddrs []resolver.Address, fallback
 		// This bypasses the cc wrapper with SubConn cache.
 		sc, err := lb.cc.cc.NewSubConn(backendAddrs, opts)
 		if err != nil {
-			grpclog.Warningf("grpclb: failed to create new SubConn: %v", err)
+			logger.Warningf("grpclb: failed to create new SubConn: %v", err)
 			return
 		}
 		sc.Connect()
@@ -173,7 +172,7 @@ func (lb *lbBalancer) refreshSubConns(backendAddrs []resolver.Address, fallback
 			// Use addrWithMD to create the SubConn.
 			sc, err := lb.cc.NewSubConn([]resolver.Address{addr}, opts)
 			if err != nil {
-				grpclog.Warningf("grpclb: failed to create new SubConn: %v", err)
+				logger.Warningf("grpclb: failed to create new SubConn: %v", err)
 				continue
 			}
 			lb.subConns[addrWithoutMD] = sc // Use the addr without MD as key for the map.
@@ -245,7 +244,7 @@ func (lb *lbBalancer) newRemoteBalancerCCWrapper() {
 	// receive ServerName as authority.
 	cc, err := grpc.DialContext(context.Background(), lb.manualResolver.Scheme()+":///grpclb.subClientConn", dopts...)
 	if err != nil {
-		grpclog.Fatalf("failed to dial: %v", err)
+		logger.Fatalf("failed to dial: %v", err)
 	}
 	ccw := &remoteBalancerCCWrapper{
 		cc:      cc,
@@ -373,9 +372,9 @@ func (ccw *remoteBalancerCCWrapper) watchRemoteBalancer() {
 		default:
 			if err != nil {
 				if err == errServerTerminatedConnection {
-					grpclog.Info(err)
+					logger.Info(err)
 				} else {
-					grpclog.Warning(err)
+					logger.Warning(err)
 				}
 			}
 		}

balancer/rls/internal/balancer.go

@@ -34,6 +34,7 @@ var (
 
 	// For overriding in tests.
 	newRLSClientFunc = newRLSClient
+	logger           = grpclog.Component("rls")
 )
 
 // rlsBalancer implements the RLS LB policy.
@@ -75,18 +76,18 @@ func (lb *rlsBalancer) run() {
 // channel accordingly.
 // TODO(easwars): Handle updates to other fields in the service config.
 func (lb *rlsBalancer) handleClientConnUpdate(ccs *balancer.ClientConnState) {
-	grpclog.Infof("rls: service config: %+v", ccs.BalancerConfig)
+	logger.Infof("rls: service config: %+v", ccs.BalancerConfig)
 	lb.mu.Lock()
 	defer lb.mu.Unlock()
 
 	if lb.done.HasFired() {
-		grpclog.Warning("rls: received service config after balancer close")
+		logger.Warning("rls: received service config after balancer close")
 		return
 	}
 
 	newCfg := ccs.BalancerConfig.(*lbConfig)
 	if lb.lbCfg.Equal(newCfg) {
-		grpclog.Info("rls: new service config matches existing config")
+		logger.Info("rls: new service config matches existing config")
 		return
 	}
 
@@ -109,12 +110,12 @@ func (lb *rlsBalancer) UpdateClientConnState(ccs balancer.ClientConnState) error
 func (lb *rlsBalancer) ResolverError(error) {
 	// ResolverError is called by gRPC when the name resolver reports an error.
 	// TODO(easwars): How do we handle this?
-	grpclog.Fatal("rls: ResolverError is not yet unimplemented")
+	logger.Fatal("rls: ResolverError is not yet unimplemented")
 }
 
 // UpdateSubConnState implements balancer.V2Balancer interface.
 func (lb *rlsBalancer) UpdateSubConnState(_ balancer.SubConn, _ balancer.SubConnState) {
-	grpclog.Fatal("rls: UpdateSubConnState is not yet implemented")
+	logger.Fatal("rls: UpdateSubConnState is not yet implemented")
 }
 
 // Cleans up the resources allocated by the LB policy including the clientConn
@@ -162,7 +163,7 @@ func (lb *rlsBalancer) updateControlChannel(newCfg *lbConfig) {
 
 	cc, err := grpc.Dial(newCfg.lookupService, dopts...)
 	if err != nil {
-		grpclog.Errorf("rls: dialRLS(%s, %v): %v", newCfg.lookupService, lb.opts, err)
+		logger.Errorf("rls: dialRLS(%s, %v): %v", newCfg.lookupService, lb.opts, err)
 		// An error from a non-blocking dial indicates something serious. We
 		// should continue to use the old control channel if one exists, and
 		// return so that the rest of the config updates can be processes.
@@ -185,14 +186,14 @@ func dialCreds(opts balancer.BuildOptions) grpc.DialOption {
 	switch {
 	case opts.DialCreds != nil:
 		if err := opts.DialCreds.OverrideServerName(server); err != nil {
-			grpclog.Warningf("rls: OverrideServerName(%s) = (%v), using Insecure", server, err)
+			logger.Warningf("rls: OverrideServerName(%s) = (%v), using Insecure", server, err)
 			return grpc.WithInsecure()
 		}
 		return grpc.WithTransportCredentials(opts.DialCreds)
 	case opts.CredsBundle != nil:
 		return grpc.WithTransportCredentials(opts.CredsBundle.TransportCredentials())
 	default:
-		grpclog.Warning("rls: no credentials available, using Insecure")
+		logger.Warning("rls: no credentials available, using Insecure")
 		return grpc.WithInsecure()
 	}
 }

balancer/rls/internal/cache/cache.go

@@ -30,6 +30,8 @@ import (
 	"google.golang.org/grpc/internal/backoff"
 )
 
+var logger = grpclog.Component("rls")
+
 // Key represents the cache key used to uniquely identify a cache entry.
 type Key struct {
 	// Path is the full path of the incoming RPC request.
@@ -175,7 +177,7 @@ func (lru *LRU) removeToFit(newSize int64) {
 		if elem == nil {
 			// This is a corner case where the cache is empty, but the new entry
 			// to be added is bigger than maxSize.
-			grpclog.Info("rls: newly added cache entry exceeds cache maxSize")
+			logger.Info("rls: newly added cache entry exceeds cache maxSize")
 			return
 		}
 
@@ -184,7 +186,7 @@ func (lru *LRU) removeToFit(newSize int64) {
 			// When the oldest entry is too new (it hasn't even spent a default
 			// minimum amount of time in the cache), we abort and allow the
 			// cache to grow bigger than the configured maxSize.
-			grpclog.Info("rls: LRU eviction finds oldest entry to be too new. Allowing cache to exceed maxSize momentarily")
+			logger.Info("rls: LRU eviction finds oldest entry to be too new. Allowing cache to exceed maxSize momentarily")
 			return
 		}
 		lru.removeElement(elem)

balancer/rls/internal/config.go

@@ -32,7 +32,6 @@ import (
 	"google.golang.org/grpc/balancer"
 	"google.golang.org/grpc/balancer/rls/internal/keys"
 	rlspb "google.golang.org/grpc/balancer/rls/internal/proto/grpc_lookup_v1"
-	"google.golang.org/grpc/grpclog"
 	"google.golang.org/grpc/internal/grpcutil"
 	"google.golang.org/grpc/resolver"
 	"google.golang.org/grpc/serviceconfig"
@@ -238,11 +237,11 @@ func (*rlsBB) ParseConfig(c json.RawMessage) (serviceconfig.LoadBalancingConfig,
 		return nil, fmt.Errorf("rls: stale_age is set, but max_age is not in service config {%+v}", string(c))
 	}
 	if staleAge >= maxAge {
-		grpclog.Info("rls: stale_age {%v} is greater than max_age {%v}, ignoring it", staleAge, maxAge)
+		logger.Info("rls: stale_age {%v} is greater than max_age {%v}, ignoring it", staleAge, maxAge)
 		staleAge = 0
 	}
 	if maxAge == 0 || maxAge > maxMaxAge {
-		grpclog.Infof("rls: max_age in service config is %v, using %v", maxAge, maxMaxAge)
+		logger.Infof("rls: max_age in service config is %v, using %v", maxAge, maxMaxAge)
 		maxAge = maxMaxAge
 	}
 

balancer/roundrobin/roundrobin.go

@@ -33,6 +33,8 @@ import (
 // Name is the name of round_robin balancer.
 const Name = "round_robin"
 
+var logger = grpclog.Component("roundrobin")
+
 // newBuilder creates a new roundrobin balancer builder.
 func newBuilder() balancer.Builder {
 	return base.NewBalancerBuilder(Name, &rrPickerBuilder{}, base.Config{HealthCheck: true})
@@ -45,7 +47,7 @@ func init() {
 type rrPickerBuilder struct{}
 
 func (*rrPickerBuilder) Build(info base.PickerBuildInfo) balancer.Picker {
-	grpclog.Infof("roundrobinPicker: newPicker called with info: %v", info)
+	logger.Infof("roundrobinPicker: newPicker called with info: %v", info)
 	if len(info.ReadySCs) == 0 {
 		return base.NewErrPicker(balancer.ErrNoSubConnAvailable)
 	}

balancer_conn_wrappers.go

@@ -220,7 +220,7 @@ func (acbw *acBalancerWrapper) UpdateAddresses(addrs []resolver.Address) {
 
 		ac, err := cc.newAddrConn(addrs, opts)
 		if err != nil {
-			channelz.Warningf(acbw.ac.channelzID, "acBalancerWrapper: UpdateAddresses: failed to newAddrConn: %v", err)
+			channelz.Warningf(logger, acbw.ac.channelzID, "acBalancerWrapper: UpdateAddresses: failed to newAddrConn: %v", err)
 			return
 		}
 		acbw.ac = ac

channelz/service/service.go

@@ -31,6 +31,7 @@ import (
 	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/connectivity"
 	"google.golang.org/grpc/credentials"
+	"google.golang.org/grpc/grpclog"
 	"google.golang.org/grpc/internal/channelz"
 	"google.golang.org/grpc/status"
 )
@@ -39,6 +40,8 @@ func init() {
 	channelz.TurnOn()
 }
 
+var logger = grpclog.Component("channelz")
+
 // RegisterChannelzServiceToServer registers the channelz service to the given server.
 func RegisterChannelzServiceToServer(s *grpc.Server) {
 	channelzgrpc.RegisterChannelzServer(s, newCZServer())