xds: let ChannelLogger log more useful information

xds/src/main/java/io/grpc/xds/InterLocalityPicker.java

@@ -20,6 +20,7 @@ import static com.google.common.base.Preconditions.checkArgument;
 import static com.google.common.base.Preconditions.checkNotNull;
 
 import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.MoreObjects;
 import com.google.common.collect.ImmutableList;
 import io.grpc.LoadBalancer.PickResult;
 import io.grpc.LoadBalancer.PickSubchannelArgs;
@@ -51,6 +52,14 @@ final class InterLocalityPicker extends SubchannelPicker {
     SubchannelPicker getPicker() {
       return childPicker;
     }
+
+    @Override
+    public String toString() {
+      return MoreObjects.toStringHelper(this)
+          .add("weight", weight)
+          .add("childPicker", childPicker)
+          .toString();
+    }
   }
 
   InterLocalityPicker(List<WeightedChildPicker> weightedChildPickers) {
@@ -99,4 +108,12 @@ final class InterLocalityPicker extends SubchannelPicker {
 
     return childPicker.pickSubchannel(args);
   }
+
+  @Override
+  public String toString() {
+    return MoreObjects.toStringHelper(this)
+        .add("weightedChildPickers", weightedChildPickers)
+        .add("totalWeight", totalWeight)
+        .toString();
+  }
 }

xds/src/main/java/io/grpc/xds/LocalityStore.java

@@ -26,7 +26,6 @@ import static io.grpc.ConnectivityState.TRANSIENT_FAILURE;
 import com.google.common.annotations.VisibleForTesting;
 import com.google.common.base.MoreObjects;
 import com.google.common.collect.ImmutableList;
-import io.grpc.ChannelLogger.ChannelLogLevel;
 import io.grpc.ConnectivityState;
 import io.grpc.ConnectivityStateInfo;
 import io.grpc.EquivalentAddressGroup;
@@ -135,6 +134,14 @@ interface LocalityStore {
         }
         return delegate.pickSubchannel(args);
       }
+
+      @Override
+      public String toString() {
+        return MoreObjects.toStringHelper(this)
+            .add("dropOverloads", dropOverloads)
+            .add("delegate", delegate)
+            .toString();
+      }
     }
 
     private static final PickerFactory pickerFactoryImpl =
@@ -324,8 +331,6 @@ interface LocalityStore {
       }
 
       if (state != null) {
-        helper.getChannelLogger().log(
-            ChannelLogLevel.INFO, "Picker updated - state: {0}, picker: {1}", state, picker);
         helper.updateBalancingState(state, picker);
       }
     }
@@ -385,6 +390,14 @@ interface LocalityStore {
           public PickResult pickSubchannel(PickSubchannelArgs args) {
             return statsStore.interceptPickResult(delegate.pickSubchannel(args), locality);
           }
+
+          @Override
+          public String toString() {
+            return MoreObjects.toStringHelper(this)
+                .add("delegate", delegate)
+                .add("locality", locality)
+                .toString();
+          }
         }
 
         currentChildState = newState;

xds/src/main/java/io/grpc/xds/XdsComms.java

@@ -36,6 +36,7 @@ import io.envoyproxy.envoy.api.v2.endpoint.LocalityLbEndpoints;
 import io.envoyproxy.envoy.service.discovery.v2.AggregatedDiscoveryServiceGrpc;
 import io.envoyproxy.envoy.type.FractionalPercent;
 import io.envoyproxy.envoy.type.FractionalPercent.DenominatorType;
+import io.grpc.ChannelLogger.ChannelLogLevel;
 import io.grpc.EquivalentAddressGroup;
 import io.grpc.LoadBalancer.Helper;
 import io.grpc.ManagedChannel;
@@ -195,6 +196,9 @@ final class XdsComms {
                     return;
                   }
 
+                  helper.getChannelLogger().log(
+                      ChannelLogLevel.DEBUG,
+                      "Received an EDS response: {0}", clusterLoadAssignment);
                   if (!firstEdsResponseReceived) {
                     firstEdsResponseReceived = true;
                     adsStreamCallback.onWorking();
@@ -277,7 +281,7 @@ final class XdsComms {
       this.localityStore = localityStore;
 
       // Assuming standard mode, and send EDS request only
-      xdsRequestWriter.onNext(
+      DiscoveryRequest edsRequest =
           DiscoveryRequest.newBuilder()
               .setNode(Node.newBuilder()
                   .setMetadata(Struct.newBuilder()
@@ -288,7 +292,9 @@ final class XdsComms {
                       .putFields(
                           "endpoints_required",
                           Value.newBuilder().setBoolValue(true).build())))
-              .setTypeUrl(EDS_TYPE_URL).build());
+              .setTypeUrl(EDS_TYPE_URL).build();
+      helper.getChannelLogger().log(ChannelLogLevel.DEBUG, "Sending EDS request {0}", edsRequest);
+      xdsRequestWriter.onNext(edsRequest);
     }
 
     AdsStream(AdsStream adsStream) {

xds/src/main/java/io/grpc/xds/XdsLbState.java

@@ -81,6 +81,7 @@ class XdsLbState {
     if (xdsComms != null) {
       xdsComms.refreshAdsStream();
     } else {
+      // TODO(zdapeng): pass a helper that has the right ChannelLogger for the oobChannel
       xdsComms = new XdsComms(channel, helper, adsStreamCallback, localityStore);
     }
 

xds/src/main/java/io/grpc/xds/XdsLoadBalancer.java

@@ -158,6 +158,8 @@ final class XdsLoadBalancer extends LoadBalancer {
       }
 
       if (!fallbackManager.isInFallbackMode()) {
+        delegate.getChannelLogger().log(
+            ChannelLogLevel.INFO, "Picker updated - state: {0}, picker: {1}", newState, newPicker);
         delegate.updateBalancingState(newState, newPicker);
       }
     }
@@ -349,6 +351,8 @@ final class XdsLoadBalancer extends LoadBalancer {
     void cancelFallback() {
       cancelFallbackTimer();
       if (fallbackBalancer != null) {
+        helper.getChannelLogger().log(
+            ChannelLogLevel.INFO, "Shutting down XDS fallback balancer");
         fallbackBalancer.shutdown();
         fallbackBalancer = null;
       }
@@ -362,7 +366,7 @@ final class XdsLoadBalancer extends LoadBalancer {
       cancelFallbackTimer();
 
       helper.getChannelLogger().log(
-          ChannelLogLevel.INFO, "Using fallback policy");
+          ChannelLogLevel.INFO, "Using XDS fallback policy");
 
       final class FallbackBalancerHelper extends ForwardingLoadBalancerHelper {
         LoadBalancer balancer;
@@ -374,6 +378,9 @@ final class XdsLoadBalancer extends LoadBalancer {
             // ignore updates from a misbehaving shutdown fallback balancer
             return;
           }
+          helper.getChannelLogger().log(
+              ChannelLogLevel.INFO,
+              "Picker updated - state: {0}, picker: {1}", newState, newPicker);
           super.updateBalancingState(newState, newPicker);
         }
 

xds/src/test/java/io/grpc/xds/XdsCommsTest.java

@@ -22,6 +22,7 @@ import static org.junit.Assert.assertFalse;
 import static org.junit.Assert.assertTrue;
 import static org.mockito.Mockito.doReturn;
 import static org.mockito.Mockito.inOrder;
+import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.never;
 import static org.mockito.Mockito.times;
 import static org.mockito.Mockito.verify;
@@ -43,6 +44,7 @@ import io.envoyproxy.envoy.api.v2.endpoint.LocalityLbEndpoints;
 import io.envoyproxy.envoy.service.discovery.v2.AggregatedDiscoveryServiceGrpc.AggregatedDiscoveryServiceImplBase;
 import io.envoyproxy.envoy.type.FractionalPercent;
 import io.envoyproxy.envoy.type.FractionalPercent.DenominatorType;
+import io.grpc.ChannelLogger;
 import io.grpc.LoadBalancer;
 import io.grpc.LoadBalancer.Helper;
 import io.grpc.LoadBalancerProvider;
@@ -146,6 +148,7 @@ public class XdsCommsTest {
         cleanupRule.register(InProcessChannelBuilder.forName(serverName).directExecutor().build());
     doReturn("fake_authority").when(helper).getAuthority();
     doReturn(syncContext).when(helper).getSynchronizationContext();
+    doReturn(mock(ChannelLogger.class)).when(helper).getChannelLogger();
     lbRegistry.register(new LoadBalancerProvider() {
       @Override
       public boolean isAvailable() {