core: channel tracing to log events for channel state change

core/src/main/java/io/grpc/internal/ChannelTracer.java

@@ -64,6 +64,9 @@ final class ChannelTracer {
     reportEvent(new ChannelTrace.Event.Builder()
         .setDescription(channelType + " created")
         .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+        // passing the timestamp in as a parameter instead of computing it right here because when
+        // parent channel and subchannel both report the same event of the subchannel (e.g. creation
+        // event of the subchannel) we want the timestamps to be exactly the same.
         .setTimestampNanos(channelCreationTimeNanos)
         .build());
   }

core/src/main/java/io/grpc/internal/InternalSubchannel.java

@@ -38,6 +38,7 @@ import io.grpc.Metadata;
 import io.grpc.MethodDescriptor;
 import io.grpc.Status;
 import io.grpc.internal.Channelz.ChannelStats;
+import io.grpc.internal.Channelz.ChannelTrace;
 import java.net.SocketAddress;
 import java.util.ArrayList;
 import java.util.Collection;
@@ -70,6 +71,7 @@ final class InternalSubchannel implements Instrumented<ChannelStats> {
   private final CallTracer callsTracer;
   @CheckForNull
   private final ChannelTracer channelTracer;
+  private final TimeProvider timeProvider;
 
   // File-specific convention: methods without GuardedBy("lock") MUST NOT be called under the lock.
   private final Object lock = new Object();
@@ -161,7 +163,8 @@ final class InternalSubchannel implements Instrumented<ChannelStats> {
       BackoffPolicy.Provider backoffPolicyProvider,
       ClientTransportFactory transportFactory, ScheduledExecutorService scheduledExecutor,
       Supplier<Stopwatch> stopwatchSupplier, ChannelExecutor channelExecutor, Callback callback,
-      Channelz channelz, CallTracer callsTracer, @Nullable ChannelTracer channelTracer) {
+      Channelz channelz, CallTracer callsTracer, @Nullable ChannelTracer channelTracer,
+      TimeProvider timeProvider) {
     this.addressGroup = Preconditions.checkNotNull(addressGroup, "addressGroup");
     this.authority = authority;
     this.userAgent = userAgent;
@@ -174,6 +177,7 @@ final class InternalSubchannel implements Instrumented<ChannelStats> {
     this.channelz = channelz;
     this.callsTracer = callsTracer;
     this.channelTracer = channelTracer;
+    this.timeProvider = timeProvider;
   }
 
   /**
@@ -314,6 +318,14 @@ final class InternalSubchannel implements Instrumented<ChannelStats> {
       Preconditions.checkState(state.getState() != SHUTDOWN,
           "Cannot transition out of SHUTDOWN to " + newState);
       state = newState;
+      if (channelTracer != null) {
+        channelTracer.reportEvent(
+            new ChannelTrace.Event.Builder()
+                .setDescription("Entering " + state + " state")
+                .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+                .setTimestampNanos(timeProvider.currentTimeNanos())
+                .build());
+      }
       channelExecutor.executeLater(new Runnable() {
           @Override
           public void run() {

core/src/main/java/io/grpc/internal/ManagedChannelImpl.java

@@ -385,6 +385,14 @@ final class ManagedChannelImpl extends ManagedChannel implements Instrumented<Ch
     shutdownNameResolverAndLoadBalancer(true);
     delayedTransport.reprocess(null);
     nameResolver = getNameResolver(target, nameResolverFactory, nameResolverParams);
+    if (channelTracer != null) {
+      channelTracer.reportEvent(
+          new ChannelTrace.Event.Builder()
+              .setDescription("Entering IDLE state")
+              .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+              .setTimestampNanos(timeProvider.currentTimeNanos())
+              .build());
+    }
     channelStateManager.gotoState(IDLE);
   }
 
@@ -666,6 +674,13 @@ final class ManagedChannelImpl extends ManagedChannel implements Instrumented<Ch
     channelExecutor.executeLater(new Runnable() {
       @Override
       public void run() {
+        if (channelTracer != null) {
+          channelTracer.reportEvent(new ChannelTrace.Event.Builder()
+              .setDescription("Entering SHUTDOWN state")
+              .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+              .setTimestampNanos(timeProvider.currentTimeNanos())
+              .build());
+        }
         channelStateManager.gotoState(SHUTDOWN);
       }
     });
@@ -724,6 +739,14 @@ final class ManagedChannelImpl extends ManagedChannel implements Instrumented<Ch
       }
     };
     updateSubchannelPicker(newPicker);
+    if (channelTracer != null) {
+      channelTracer.reportEvent(
+          new ChannelTrace.Event.Builder()
+              .setDescription("Entering TRANSIENT_FAILURE state")
+              .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+              .setTimestampNanos(timeProvider.currentTimeNanos())
+              .build());
+    }
     channelStateManager.gotoState(TRANSIENT_FAILURE);
   }
 
@@ -1034,7 +1057,8 @@ final class ManagedChannelImpl extends ManagedChannel implements Instrumented<Ch
           },
           channelz,
           callTracerFactory.create(),
-          subchannelTracer);
+          subchannelTracer,
+          timeProvider);
       if (channelTracer != null) {
         channelTracer.reportEvent(new ChannelTrace.Event.Builder()
             .setDescription("Child channel created")
@@ -1085,6 +1109,14 @@ final class ManagedChannelImpl extends ManagedChannel implements Instrumented<Ch
               // It's not appropriate to report SHUTDOWN state from lb.
               // Ignore the case of newState == SHUTDOWN for now.
               if (newState != SHUTDOWN) {
+                if (channelTracer != null) {
+                  channelTracer.reportEvent(
+                      new ChannelTrace.Event.Builder()
+                          .setDescription("Entering " + newState + " state")
+                          .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+                          .setTimestampNanos(timeProvider.currentTimeNanos())
+                          .build());
+                }
                 channelStateManager.gotoState(newState);
               }
             }
@@ -1111,7 +1143,7 @@ final class ManagedChannelImpl extends ManagedChannel implements Instrumented<Ch
       }
       final OobChannel oobChannel = new OobChannel(
           authority, oobExecutorPool, transportFactory.getScheduledExecutorService(),
-          channelExecutor, callTracerFactory.create(), oobChannelTracer, channelz);
+          channelExecutor, callTracerFactory.create(), oobChannelTracer, channelz, timeProvider);
       if (channelTracer != null) {
         channelTracer.reportEvent(new ChannelTrace.Event.Builder()
             .setDescription("Child channel created")
@@ -1142,7 +1174,8 @@ final class ManagedChannelImpl extends ManagedChannel implements Instrumented<Ch
           },
           channelz,
           callTracerFactory.create(),
-          subchannelTracer);
+          subchannelTracer,
+          timeProvider);
       if (oobChannelTracer != null) {
         oobChannelTracer.reportEvent(new ChannelTrace.Event.Builder()
             .setDescription("Child channel created")

core/src/main/java/io/grpc/internal/OobChannel.java

@@ -26,6 +26,7 @@ import com.google.common.util.concurrent.SettableFuture;
 import io.grpc.Attributes;
 import io.grpc.CallOptions;
 import io.grpc.ClientCall;
+import io.grpc.ConnectivityState;
 import io.grpc.ConnectivityStateInfo;
 import io.grpc.Context;
 import io.grpc.EquivalentAddressGroup;
@@ -39,6 +40,7 @@ import io.grpc.Metadata;
 import io.grpc.MethodDescriptor;
 import io.grpc.Status;
 import io.grpc.internal.Channelz.ChannelStats;
+import io.grpc.internal.Channelz.ChannelTrace;
 import io.grpc.internal.ClientCallImpl.ClientTransportProvider;
 import java.util.Collections;
 import java.util.concurrent.CountDownLatch;
@@ -75,6 +77,7 @@ final class OobChannel extends ManagedChannel implements Instrumented<ChannelSta
   private final CallTracer channelCallsTracer;
   @CheckForNull
   private final ChannelTracer channelTracer;
+  private final TimeProvider timeProvider;
 
   private final ClientTransportProvider transportProvider = new ClientTransportProvider() {
     @Override
@@ -95,7 +98,8 @@ final class OobChannel extends ManagedChannel implements Instrumented<ChannelSta
   OobChannel(
       String authority, ObjectPool<? extends Executor> executorPool,
       ScheduledExecutorService deadlineCancellationExecutor, ChannelExecutor channelExecutor,
-      CallTracer callsTracer, @Nullable  ChannelTracer channelTracer, Channelz channelz) {
+      CallTracer callsTracer, @Nullable  ChannelTracer channelTracer, Channelz channelz,
+      TimeProvider timeProvider) {
     this.authority = checkNotNull(authority, "authority");
     this.executorPool = checkNotNull(executorPool, "executorPool");
     this.executor = checkNotNull(executorPool.getObject(), "executor");
@@ -126,6 +130,7 @@ final class OobChannel extends ManagedChannel implements Instrumented<ChannelSta
       });
     this.channelCallsTracer = callsTracer;
     this.channelTracer = channelTracer;
+    this.timeProvider = timeProvider;
   }
 
   // Must be called only once, right after the OobChannel is created.
@@ -203,6 +208,14 @@ final class OobChannel extends ManagedChannel implements Instrumented<ChannelSta
     return terminatedLatch.await(time, unit);
   }
 
+  @Override
+  public ConnectivityState getState(boolean requestConnectionIgnored) {
+    if (subchannel == null) {
+      return ConnectivityState.IDLE;
+    }
+    return subchannel.getState();
+  }
+
   @Override
   public ManagedChannel shutdown() {
     shutdown = true;
@@ -224,6 +237,14 @@ final class OobChannel extends ManagedChannel implements Instrumented<ChannelSta
   }
 
   void handleSubchannelStateChange(final ConnectivityStateInfo newState) {
+    if (channelTracer != null) {
+      channelTracer.reportEvent(
+          new ChannelTrace.Event.Builder()
+              .setDescription("Entering " + newState.getState() + " state")
+              .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+              .setTimestampNanos(timeProvider.currentTimeNanos())
+              .build());
+    }
     switch (newState.getState()) {
       case READY:
       case IDLE:

core/src/test/java/io/grpc/internal/InternalSubchannelTest.java

@@ -951,7 +951,13 @@ public class InternalSubchannelTest {
     internalSubchannel = new InternalSubchannel(addressGroup, AUTHORITY, USER_AGENT,
         mockBackoffPolicyProvider, mockTransportFactory, fakeClock.getScheduledExecutorService(),
         fakeClock.getStopwatchSupplier(), channelExecutor, mockInternalSubchannelCallback,
-        channelz, CallTracer.getDefaultFactory().create(), null);
+        channelz, CallTracer.getDefaultFactory().create(), null,
+        new TimeProvider() {
+          @Override
+          public long currentTimeNanos() {
+            return fakeClock.getTicker().read();
+          }
+        });
   }
 
   private void assertNoCallbackInvoke() {

core/src/test/java/io/grpc/internal/ManagedChannelImplTest.java

@@ -2129,6 +2129,49 @@ public class ManagedChannelImplTest {
         .build());
   }
 
+  @Test
+  public void channelTracing_stateChangeEvent() throws Exception {
+    channelBuilder.maxTraceEvents(10);
+    createChannel();
+    timer.forwardNanos(1234);
+    helper.updateBalancingState(CONNECTING, mockPicker);
+    assertThat(getStats(channel).channelTrace.events).contains(new ChannelTrace.Event.Builder()
+        .setDescription("Entering CONNECTING state")
+        .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+        .setTimestampNanos(timer.getTicker().read())
+        .build());
+  }
+
+  @Test
+  public void channelTracing_subchannelStateChangeEvent() throws Exception {
+    channelBuilder.maxTraceEvents(10);
+    createChannel();
+    AbstractSubchannel subchannel =
+        (AbstractSubchannel) helper.createSubchannel(addressGroup, Attributes.EMPTY);
+    timer.forwardNanos(1234);
+    subchannel.obtainActiveTransport();
+    assertThat(getStats(subchannel).channelTrace.events).contains(new ChannelTrace.Event.Builder()
+        .setDescription("Entering CONNECTING state")
+        .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+        .setTimestampNanos(timer.getTicker().read())
+        .build());
+  }
+
+  @Test
+  public void channelTracing_oobChannelStateChangeEvent() throws Exception {
+    channelBuilder.maxTraceEvents(10);
+    createChannel();
+    OobChannel oobChannel = (OobChannel) helper.createOobChannel(addressGroup, "authority");
+    timer.forwardNanos(1234);
+    oobChannel.handleSubchannelStateChange(
+        ConnectivityStateInfo.forNonError(ConnectivityState.CONNECTING));
+    assertThat(getStats(oobChannel).channelTrace.events).contains(new ChannelTrace.Event.Builder()
+        .setDescription("Entering CONNECTING state")
+        .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
+        .setTimestampNanos(timer.getTicker().read())
+        .build());
+  }
+
   @Test
   public void channelTracing_oobChannelCreationEvents() throws Exception {
     channelBuilder.maxTraceEvents(10);