grpclog: remove Debugf method to avoid unnecessary evaluation (#7330)

grpc · Jun 24, 2024 · 8c80220 · 8c80220
1 parent c8568c9
commit 8c80220
Show file tree

Hide file tree

Showing 6 changed files with 42 additions and 35 deletions.
diff --git a/internal/grpclog/prefixLogger.go b/internal/grpclog/prefixLogger.go
@@ -61,24 +61,6 @@ func (pl *PrefixLogger) Errorf(format string, args ...any) {
 	ErrorDepth(1, fmt.Sprintf(format, args...))
 }
 
-// Debugf does info logging at verbose level 2.
-func (pl *PrefixLogger) Debugf(format string, args ...any) {
-	// TODO(6044): Refactor interfaces LoggerV2 and DepthLogger, and maybe
-	// rewrite PrefixLogger a little to ensure that we don't use the global
-	// `Logger` here, and instead use the `logger` field.
-	if !Logger.V(2) {
-		return
-	}
-	if pl != nil {
-		// Handle nil, so the tests can pass in a nil logger.
-		format = pl.prefix + format
-		pl.logger.InfoDepth(1, fmt.Sprintf(format, args...))
-		return
-	}
-	InfoDepth(1, fmt.Sprintf(format, args...))
-
-}
-
 // V reports whether verbosity level l is at least the requested verbose level.
 func (pl *PrefixLogger) V(l int) bool {
 	// TODO(6044): Refactor interfaces LoggerV2 and DepthLogger, and maybe

diff --git a/internal/xds/bootstrap/bootstrap.go b/internal/xds/bootstrap/bootstrap.go
@@ -509,7 +509,9 @@ func bootstrapConfigFromEnvVariable() ([]byte, error) {
 	fContent := envconfig.XDSBootstrapFileContent
 
 	if fName != "" {
-		logger.Debugf("Using bootstrap file with name %q", fName)
+		if logger.V(2) {
+			logger.Infof("Using bootstrap file with name %q", fName)
+		}
 		return bootstrapFileReadFunc(fName)
 	}
 

diff --git a/xds/internal/balancer/priority/balancer_priority.go b/xds/internal/balancer/priority/balancer_priority.go
@@ -83,7 +83,9 @@ var (
 // Caller must hold b.mu.
 func (b *priorityBalancer) syncPriority(childUpdating string) {
 	if b.inhibitPickerUpdates {
-		b.logger.Debugf("Skipping update from child policy %q", childUpdating)
+		if b.logger.V(2) {
+			b.logger.Infof("Skipping update from child policy %q", childUpdating)
+		}
 		return
 	}
 	for p, name := range b.priorities {
@@ -99,12 +101,16 @@ func (b *priorityBalancer) syncPriority(childUpdating string) {
 			(child.state.ConnectivityState == connectivity.Connecting && child.initTimer != nil) ||
 			p == len(b.priorities)-1 {
 			if b.childInUse != child.name || child.name == childUpdating {
-				b.logger.Debugf("childInUse, childUpdating: %q, %q", b.childInUse, child.name)
+				if b.logger.V(2) {
+					b.logger.Infof("childInUse, childUpdating: %q, %q", b.childInUse, child.name)
+				}
 				// If we switch children or the child in use just updated its
 				// picker, push the child's picker to the parent.
 				b.cc.UpdateState(child.state)
 			}
-			b.logger.Debugf("Switching to (%q, %v) in syncPriority", child.name, p)
+			if b.logger.V(2) {
+				b.logger.Infof("Switching to (%q, %v) in syncPriority", child.name, p)
+			}
 			b.switchToChild(child, p)
 			break
 		}

diff --git a/xds/internal/balancer/ringhash/ring.go b/xds/internal/balancer/ringhash/ring.go
@@ -67,11 +67,15 @@ type ringEntry struct {
 //
 // Must be called with a non-empty subConns map.
 func newRing(subConns *resolver.AddressMap, minRingSize, maxRingSize uint64, logger *grpclog.PrefixLogger) *ring {
-	logger.Debugf("newRing: number of subConns is %d, minRingSize is %d, maxRingSize is %d", subConns.Len(), minRingSize, maxRingSize)
+	if logger.V(2) {
+		logger.Infof("newRing: number of subConns is %d, minRingSize is %d, maxRingSize is %d", subConns.Len(), minRingSize, maxRingSize)
+	}
 
 	// https://github.com/envoyproxy/envoy/blob/765c970f06a4c962961a0e03a467e165b276d50f/source/common/upstream/ring_hash_lb.cc#L114
 	normalizedWeights, minWeight := normalizeWeights(subConns)
-	logger.Debugf("newRing: normalized subConn weights is %v", normalizedWeights)
+	if logger.V(2) {
+		logger.Infof("newRing: normalized subConn weights is %v", normalizedWeights)
+	}
 
 	// Normalized weights for {3,3,4} is {0.3,0.3,0.4}.
 
@@ -82,7 +86,9 @@ func newRing(subConns *resolver.AddressMap, minRingSize, maxRingSize uint64, log
 	scale := math.Min(math.Ceil(minWeight*float64(minRingSize))/minWeight, float64(maxRingSize))
 	ringSize := math.Ceil(scale)
 	items := make([]*ringEntry, 0, int(ringSize))
-	logger.Debugf("newRing: creating new ring of size %v", ringSize)
+	if logger.V(2) {
+		logger.Infof("newRing: creating new ring of size %v", ringSize)
+	}
 
 	// For each entry, scale*weight nodes are generated in the ring.
 	//

diff --git a/xds/internal/xdsclient/authority.go b/xds/internal/xdsclient/authority.go
@@ -229,7 +229,9 @@ func (a *authority) updateResourceStateAndScheduleCallbacks(rType xdsresource.Ty
 				}
 			}
 			// Sync cache.
-			a.logger.Debugf("Resource type %q with name %q added to cache", rType.TypeName(), name)
+			if a.logger.V(2) {
+				a.logger.Infof("Resource type %q with name %q added to cache", rType.TypeName(), name)
+			}
 			state.cache = uErr.resource
 			// Set status to ACK, and clear error state. The metadata might be a
 			// NACK metadata because some other resources in the same response
@@ -454,7 +456,9 @@ func (a *authority) close() {
 }
 
 func (a *authority) watchResource(rType xdsresource.Type, resourceName string, watcher xdsresource.ResourceWatcher) func() {
-	a.logger.Debugf("New watch for type %q, resource name %q", rType.TypeName(), resourceName)
+	if a.logger.V(2) {
+		a.logger.Infof("New watch for type %q, resource name %q", rType.TypeName(), resourceName)
+	}
 	a.resourcesMu.Lock()
 	defer a.resourcesMu.Unlock()
 
@@ -471,7 +475,9 @@ func (a *authority) watchResource(rType xdsresource.Type, resourceName string, w
 	// instruct the transport layer to send a DiscoveryRequest for the same.
 	state := resources[resourceName]
 	if state == nil {
-		a.logger.Debugf("First watch for type %q, resource name %q", rType.TypeName(), resourceName)
+		if a.logger.V(2) {
+			a.logger.Infof("First watch for type %q, resource name %q", rType.TypeName(), resourceName)
+		}
 		state = &resourceState{
 			watchers: make(map[xdsresource.ResourceWatcher]bool),
 			md:       xdsresource.UpdateMetadata{Status: xdsresource.ServiceStatusRequested},
@@ -510,7 +516,9 @@ func (a *authority) watchResource(rType xdsresource.Type, resourceName string, w
 		// There are no more watchers for this resource, delete the state
 		// associated with it, and instruct the transport to send a request
 		// which does not include this resource name.
-		a.logger.Debugf("Removing last watch for type %q, resource name %q", rType.TypeName(), resourceName)
+		if a.logger.V(2) {
+			a.logger.Infof("Removing last watch for type %q, resource name %q", rType.TypeName(), resourceName)
+		}
 		delete(resources, resourceName)
 		a.sendDiscoveryRequestLocked(rType, resources)
 	}

diff --git a/xds/internal/xdsclient/transport/transport.go b/xds/internal/xdsclient/transport/transport.go
@@ -48,8 +48,7 @@ import (
 
 // Any per-RPC level logs which print complete request or response messages
 // should be gated at this verbosity level. Other per-RPC level logs which print
-// terse output should be at `INFO` and verbosity 2, which corresponds to using
-// the `Debugf` method on the logger.
+// terse output should be at `INFO` and verbosity 2.
 const perRPCVerbosityLevel = 9
 
 type adsStream = v3adsgrpc.AggregatedDiscoveryService_StreamAggregatedResourcesClient
@@ -298,7 +297,9 @@ func (t *Transport) sendAggregatedDiscoveryServiceRequest(stream adsStream, send
 	if t.logger.V(perRPCVerbosityLevel) {
 		t.logger.Infof("ADS request sent: %v", pretty.ToJSON(req))
 	} else {
-		t.logger.Debugf("ADS request sent for type %q, resources: %v, version %q, nonce %q", resourceURL, resourceNames, version, nonce)
+		if t.logger.V(2) {
+			t.logger.Infof("ADS request sent for type %q, resources: %v, version %q, nonce %q", resourceURL, resourceNames, version, nonce)
+		}
 	}
 	t.onSendHandler(&ResourceSendInfo{URL: resourceURL, ResourceNames: resourceNames})
 	return nil
@@ -311,8 +312,8 @@ func (t *Transport) recvAggregatedDiscoveryServiceResponse(stream adsStream) (re
 	}
 	if t.logger.V(perRPCVerbosityLevel) {
 		t.logger.Infof("ADS response received: %v", pretty.ToJSON(resp))
-	} else {
-		t.logger.Debugf("ADS response received for type %q, version %q, nonce %q", resp.GetTypeUrl(), resp.GetVersionInfo(), resp.GetNonce())
+	} else if t.logger.V(2) {
+		t.logger.Infof("ADS response received for type %q, version %q, nonce %q", resp.GetTypeUrl(), resp.GetVersionInfo(), resp.GetNonce())
 	}
 	return resp.GetResources(), resp.GetTypeUrl(), resp.GetVersionInfo(), resp.GetNonce(), nil
 }
@@ -512,7 +513,9 @@ func (t *Transport) recv(stream adsStream) bool {
 			stream:  stream,
 			version: rVersion,
 		})
-		t.logger.Debugf("Sending ACK for resource type: %q, version: %q, nonce: %q", url, rVersion, nonce)
+		if t.logger.V(2) {
+			t.logger.Infof("Sending ACK for resource type: %q, version: %q, nonce: %q", url, rVersion, nonce)
+		}
 	}
 }