core: channel tracing to log lb policy changes

5 files changed, 126 insertions, 14 deletions

diff --git a/core/src/main/java/io/grpc/LoadBalancer.java b/core/src/main/java/io/grpc/LoadBalancer.java
index 633bf5263..9256ea810 100644
--- a/core/src/main/java/io/grpc/LoadBalancer.java
+++ b/core/src/main/java/io/grpc/LoadBalancer.java
@@ -154,6 +154,11 @@ public abstract class LoadBalancer {
    */
   public abstract void shutdown();
 
+  @Override
+  public String toString() {
+    return getClass().getSimpleName();
+  }
+
   /**
    * The main balancing logic.  It <strong>must be thread-safe</strong>. Typically it should only
    * synchronize on its own state, and avoid synchronizing with the LoadBalancer's state.
diff --git a/core/src/main/java/io/grpc/internal/AutoConfiguredLoadBalancerFactory.java b/core/src/main/java/io/grpc/internal/AutoConfiguredLoadBalancerFactory.java
index 80505bce3..ce063bd79 100644
--- a/core/src/main/java/io/grpc/internal/AutoConfiguredLoadBalancerFactory.java
+++ b/core/src/main/java/io/grpc/internal/AutoConfiguredLoadBalancerFactory.java
@@ -16,6 +16,8 @@
 
 package io.grpc.internal;
 
+import static com.google.common.base.Preconditions.checkNotNull;
+
 import com.google.common.annotations.VisibleForTesting;
 import io.grpc.Attributes;
 import io.grpc.ConnectivityState;
@@ -28,10 +30,12 @@ import io.grpc.LoadBalancer.PickSubchannelArgs;
 import io.grpc.LoadBalancer.SubchannelPicker;
 import io.grpc.PickFirstBalancerFactory;
 import io.grpc.Status;
+import io.grpc.internal.Channelz.ChannelTrace;
 import java.lang.reflect.Method;
 import java.util.List;
 import java.util.Locale;
 import java.util.Map;
+import javax.annotation.CheckForNull;
 import javax.annotation.Nullable;
 
 final class AutoConfiguredLoadBalancerFactory extends LoadBalancer.Factory {
@@ -43,11 +47,20 @@ final class AutoConfiguredLoadBalancerFactory extends LoadBalancer.Factory {
   static final String GRPCLB_LOAD_BALANCER_FACTORY_NAME =
       "io.grpc.grpclb.GrpclbLoadBalancerFactory";
 
-  AutoConfiguredLoadBalancerFactory() {}
+  @Nullable
+  private final ChannelTracer channelTracer;
+  @Nullable
+  private final TimeProvider timeProvider;
+
+  AutoConfiguredLoadBalancerFactory(
+      @Nullable ChannelTracer channelTracer, @Nullable TimeProvider timeProvider) {
+    this.channelTracer = channelTracer;
+    this.timeProvider = timeProvider;
+  }
 
   @Override
   public LoadBalancer newLoadBalancer(Helper helper) {
-    return new AutoConfiguredLoadBalancer(helper);
+    return new AutoConfiguredLoadBalancer(helper, channelTracer, timeProvider);
   }
 
   private static final class NoopLoadBalancer extends LoadBalancer {
@@ -71,11 +84,21 @@ final class AutoConfiguredLoadBalancerFactory extends LoadBalancer.Factory {
     private final Helper helper;
     private LoadBalancer delegate;
     private LoadBalancer.Factory delegateFactory;
+    @CheckForNull
+    private ChannelTracer channelTracer;
+    @Nullable
+    private final TimeProvider timeProvider;
 
-    AutoConfiguredLoadBalancer(Helper helper) {
+    AutoConfiguredLoadBalancer(
+        Helper helper, @Nullable ChannelTracer channelTracer, @Nullable TimeProvider timeProvider) {
       this.helper = helper;
       delegateFactory = PickFirstBalancerFactory.getInstance();
       delegate = delegateFactory.newLoadBalancer(helper);
+      this.channelTracer = channelTracer;
+      this.timeProvider = timeProvider;
+      if (channelTracer != null) {
+        checkNotNull(timeProvider, "timeProvider");
+      }
     }
 
     //  Must be run inside ChannelExecutor.
@@ -101,7 +124,15 @@ final class AutoConfiguredLoadBalancerFactory extends LoadBalancer.Factory {
         helper.updateBalancingState(ConnectivityState.CONNECTING, new EmptyPicker());
         delegate.shutdown();
         delegateFactory = newlbf;
+        LoadBalancer old = delegate;
         delegate = delegateFactory.newLoadBalancer(helper);
+        if (channelTracer != null) {
+          channelTracer.reportEvent(new ChannelTrace.Event.Builder()
+              .setDescription("Load balancer changed from " + old + " to " + delegate)
+              .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+              .setTimestampNanos(timeProvider.currentTimeNanos())
+              .build());
+        }
       }
       getDelegate().handleResolvedAddressGroups(servers, attributes);
     }
diff --git a/core/src/main/java/io/grpc/internal/ManagedChannelImpl.java b/core/src/main/java/io/grpc/internal/ManagedChannelImpl.java
index dc203b016..dc582b9d5 100644
--- a/core/src/main/java/io/grpc/internal/ManagedChannelImpl.java
+++ b/core/src/main/java/io/grpc/internal/ManagedChannelImpl.java
@@ -552,8 +552,16 @@ final class ManagedChannelImpl extends ManagedChannel implements
     this.nameResolverFactory = builder.getNameResolverFactory();
     this.nameResolverParams = checkNotNull(builder.getNameResolverParams(), "nameResolverParams");
     this.nameResolver = getNameResolver(target, nameResolverFactory, nameResolverParams);
+    this.timeProvider = checkNotNull(timeProvider, "timeProvider");
+    maxTraceEvents = builder.maxTraceEvents;
+    if (maxTraceEvents > 0) {
+      long currentTimeNanos = timeProvider.currentTimeNanos();
+      channelTracer = new ChannelTracer(builder.maxTraceEvents, currentTimeNanos, "Channel");
+    } else {
+      channelTracer = null;
+    }
     if (builder.loadBalancerFactory == null) {
-      this.loadBalancerFactory = new AutoConfiguredLoadBalancerFactory();
+      this.loadBalancerFactory = new AutoConfiguredLoadBalancerFactory(channelTracer, timeProvider);
     } else {
       this.loadBalancerFactory = builder.loadBalancerFactory;
     }
@@ -606,7 +614,6 @@ final class ManagedChannelImpl extends ManagedChannel implements
 
     this.channelBufferLimit = builder.retryBufferSize;
     this.perRpcBufferLimit = builder.perRpcBufferLimit;
-    this.timeProvider = checkNotNull(timeProvider, "timeProvider");
     this.callTracerFactory = new CallTracer.Factory() {
       @Override
       public CallTracer create() {
@@ -617,13 +624,6 @@ final class ManagedChannelImpl extends ManagedChannel implements
     this.channelz = checkNotNull(builder.channelz);
     channelz.addRootChannel(this);
 
-    maxTraceEvents = builder.maxTraceEvents;
-    if (maxTraceEvents > 0) {
-      long currentTimeNanos = timeProvider.currentTimeNanos();
-      channelTracer = new ChannelTracer(builder.maxTraceEvents, currentTimeNanos, "Channel");
-    } else {
-      channelTracer = null;
-    }
     logger.log(Level.FINE, "[{0}] Created with target {1}", new Object[] {getLogId(), target});
   }
 
diff --git a/core/src/test/java/io/grpc/internal/AutoConfiguredLoadBalancerFactoryTest.java b/core/src/test/java/io/grpc/internal/AutoConfiguredLoadBalancerFactoryTest.java
index 1542a6fac..9853b4b05 100644
--- a/core/src/test/java/io/grpc/internal/AutoConfiguredLoadBalancerFactoryTest.java
+++ b/core/src/test/java/io/grpc/internal/AutoConfiguredLoadBalancerFactoryTest.java
@@ -19,6 +19,8 @@ package io.grpc.internal;
 import static com.google.common.truth.Truth.assertThat;
 import static org.junit.Assert.assertTrue;
 import static org.junit.Assert.fail;
+import static org.mockito.Mockito.RETURNS_DEEP_STUBS;
+import static org.mockito.Mockito.mock;
 
 import io.grpc.Attributes;
 import io.grpc.ConnectivityState;
@@ -52,7 +54,8 @@ import org.junit.runners.JUnit4;
  */
 @RunWith(JUnit4.class)
 public class AutoConfiguredLoadBalancerFactoryTest {
-  private final AutoConfiguredLoadBalancerFactory lbf = new AutoConfiguredLoadBalancerFactory();
+  private final AutoConfiguredLoadBalancerFactory lbf =
+      new AutoConfiguredLoadBalancerFactory(null, null);
 
   @Test
   public void newLoadBalancer_isAuto() {
@@ -258,6 +261,79 @@ public class AutoConfiguredLoadBalancerFactoryTest {
     }
   }
 
+  @Test
+  public void channelTracing_lbPolicyChanged() {
+    ChannelTracer channelTracer = new ChannelTracer(100, 1000, "dummy_type");
+    TimeProvider timeProvider = new TimeProvider() {
+      @Override
+      public long currentTimeNanos() {
+        return 101;
+      }
+    };
+
+    Channelz.ChannelStats.Builder statsBuilder = new Channelz.ChannelStats.Builder();
+    channelTracer.updateBuilder(statsBuilder);
+    List<EquivalentAddressGroup> servers =
+        Collections.singletonList(
+            new EquivalentAddressGroup(new SocketAddress(){}, Attributes.EMPTY));
+    Helper helper = new TestHelper() {
+      @Override
+      public Subchannel createSubchannel(List<EquivalentAddressGroup> addrs, Attributes attrs) {
+        return new TestSubchannel(addrs, attrs);
+      }
+
+      @Override
+      public ManagedChannel createOobChannel(EquivalentAddressGroup eag, String authority) {
+        return mock(ManagedChannel.class, RETURNS_DEEP_STUBS);
+      }
+
+      @Override
+      public String getAuthority() {
+        return "fake_authority";
+      }
+
+      @Override
+      public void updateBalancingState(ConnectivityState newState, SubchannelPicker newPicker) {
+        // noop
+      }
+    };
+    int prevNumOfEvents = statsBuilder.build().channelTrace.events.size();
+
+    LoadBalancer lb =
+        new AutoConfiguredLoadBalancerFactory(channelTracer, timeProvider).newLoadBalancer(helper);
+    lb.handleResolvedAddressGroups(servers, Attributes.EMPTY);
+    channelTracer.updateBuilder(statsBuilder);
+    assertThat(statsBuilder.build().channelTrace.events).hasSize(prevNumOfEvents);
+
+    Map<String, Object> serviceConfig = new HashMap<String, Object>();
+    serviceConfig.put("loadBalancingPolicy", "round_robin");
+    lb.handleResolvedAddressGroups(servers,
+        Attributes.newBuilder()
+            .set(GrpcAttributes.NAME_RESOLVER_SERVICE_CONFIG, serviceConfig).build());
+    channelTracer.updateBuilder(statsBuilder);
+    assertThat(statsBuilder.build().channelTrace.events).hasSize(prevNumOfEvents + 1);
+    assertThat(statsBuilder.build().channelTrace.events.get(prevNumOfEvents).description)
+        .isEqualTo("Load balancer changed from PickFirstBalancer to RoundRobinLoadBalancer");
+    prevNumOfEvents = statsBuilder.build().channelTrace.events.size();
+
+    serviceConfig.put("loadBalancingPolicy", "round_robin");
+    lb.handleResolvedAddressGroups(servers,
+        Attributes.newBuilder()
+            .set(GrpcAttributes.NAME_RESOLVER_SERVICE_CONFIG, serviceConfig).build());
+    channelTracer.updateBuilder(statsBuilder);
+    assertThat(statsBuilder.build().channelTrace.events).hasSize(prevNumOfEvents);
+
+    servers = Collections.singletonList(new EquivalentAddressGroup(
+        new SocketAddress(){},
+        Attributes.newBuilder().set(GrpcAttributes.ATTR_LB_ADDR_AUTHORITY, "ok").build()));
+    lb.handleResolvedAddressGroups(servers, Attributes.EMPTY);
+
+    channelTracer.updateBuilder(statsBuilder);
+    assertThat(statsBuilder.build().channelTrace.events).hasSize(prevNumOfEvents + 1);
+    assertThat(statsBuilder.build().channelTrace.events.get(prevNumOfEvents).description)
+        .isEqualTo("Load balancer changed from RoundRobinLoadBalancer to GrpclbLoadBalancer");
+  }
+
   public static class ForwardingLoadBalancer extends LoadBalancer {
     private final LoadBalancer delegate;
 
diff --git a/core/src/test/java/io/grpc/internal/ManagedChannelImplTest.java b/core/src/test/java/io/grpc/internal/ManagedChannelImplTest.java
index ffc92b1bf..74e95c88e 100644
--- a/core/src/test/java/io/grpc/internal/ManagedChannelImplTest.java
+++ b/core/src/test/java/io/grpc/internal/ManagedChannelImplTest.java
@@ -2761,7 +2761,7 @@ public class ManagedChannelImplTest {
 
     ManagedChannel mychannel = new CustomBuilder()
         .nameResolverFactory(factory)
-        .loadBalancerFactory(new AutoConfiguredLoadBalancerFactory()).build();
+        .loadBalancerFactory(new AutoConfiguredLoadBalancerFactory(null, null)).build();
 
     ClientCall<Void, Void> call1 =
         mychannel.newCall(TestMethodDescriptors.voidMethod(), CallOptions.DEFAULT);