core: create subchannelLogger outside InternalSubchannel and before calling start() (#5775)

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

@@ -78,7 +78,7 @@ final class InternalSubchannel implements InternalInstrumented<ChannelStats>, Tr
   private final InternalChannelz channelz;
   private final CallTracer callsTracer;
   private final ChannelTracer channelTracer;
-  private final ChannelLoggerImpl channelLogger;
+  private final ChannelLogger channelLogger;
 
   // File-specific convention: methods without GuardedBy("lock") MUST NOT be called under the lock.
   private final Object lock = new Object();
@@ -167,7 +167,7 @@ final class InternalSubchannel implements InternalInstrumented<ChannelStats>, Tr
       ClientTransportFactory transportFactory, ScheduledExecutorService scheduledExecutor,
       Supplier<Stopwatch> stopwatchSupplier, SynchronizationContext syncContext, Callback callback,
       InternalChannelz channelz, CallTracer callsTracer, ChannelTracer channelTracer,
-      InternalLogId logId, TimeProvider timeProvider) {
+      InternalLogId logId, ChannelLogger channelLogger) {
     Preconditions.checkNotNull(addressGroups, "addressGroups");
     Preconditions.checkArgument(!addressGroups.isEmpty(), "addressGroups is empty");
     checkListHasNoNulls(addressGroups, "addressGroups contains null entry");
@@ -184,8 +184,8 @@ final class InternalSubchannel implements InternalInstrumented<ChannelStats>, Tr
     this.channelz = channelz;
     this.callsTracer = callsTracer;
     this.channelTracer = Preconditions.checkNotNull(channelTracer, "channelTracer");
-    this.logId = InternalLogId.allocate("Subchannel", authority);
-    this.channelLogger = new ChannelLoggerImpl(channelTracer, timeProvider);
+    this.logId = Preconditions.checkNotNull(logId, "logId");
+    this.channelLogger = Preconditions.checkNotNull(channelLogger, "channelLogger");
   }
 
   ChannelLogger getChannelLogger() {

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

@@ -1148,7 +1148,8 @@ final class ManagedChannelImpl extends ManagedChannel implements
       checkState(!terminated, "Channel is terminated");
       long oobChannelCreationTime = timeProvider.currentTimeNanos();
       InternalLogId oobLogId = InternalLogId.allocate("OobChannel", /*details=*/ null);
-      InternalLogId subchannelLogId = InternalLogId.allocate("Subchannel-OOB", /*details=*/ null);
+      InternalLogId subchannelLogId =
+          InternalLogId.allocate("Subchannel-OOB", /*details=*/ authority);
       ChannelTracer oobChannelTracer =
           new ChannelTracer(
               oobLogId, maxTraceEvents, oobChannelCreationTime,
@@ -1165,6 +1166,7 @@ final class ManagedChannelImpl extends ManagedChannel implements
       ChannelTracer subchannelTracer =
           new ChannelTracer(subchannelLogId, maxTraceEvents, oobChannelCreationTime,
               "Subchannel for " + addressGroup);
+      ChannelLogger subchannelLogger = new ChannelLoggerImpl(subchannelTracer, timeProvider);
       final class ManagedOobChannelCallback extends InternalSubchannel.Callback {
         @Override
         void onTerminated(InternalSubchannel is) {
@@ -1191,7 +1193,7 @@ final class ManagedChannelImpl extends ManagedChannel implements
           callTracerFactory.create(),
           subchannelTracer,
           subchannelLogId,
-          timeProvider);
+          subchannelLogger);
       oobChannelTracer.reportEvent(new ChannelTrace.Event.Builder()
           .setDescription("Child Subchannel created")
           .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
@@ -1408,6 +1410,9 @@ final class ManagedChannelImpl extends ManagedChannel implements
   private final class SubchannelImpl extends AbstractSubchannel {
     final CreateSubchannelArgs args;
     final LbHelperImpl helper;
+    final InternalLogId subchannelLogId;
+    final ChannelLoggerImpl subchannelLogger;
+    final ChannelTracer subchannelTracer;
     SubchannelStateListener listener;
     InternalSubchannel subchannel;
     boolean started;
@@ -1417,6 +1422,11 @@ final class ManagedChannelImpl extends ManagedChannel implements
     SubchannelImpl(CreateSubchannelArgs args, LbHelperImpl helper) {
       this.args = checkNotNull(args, "args");
       this.helper = checkNotNull(helper, "helper");
+      subchannelLogId = InternalLogId.allocate("Subchannel", /*details=*/ authority());
+      subchannelTracer = new ChannelTracer(
+          subchannelLogId, maxTraceEvents, timeProvider.currentTimeNanos(),
+          "Subchannel for " + args.getAddresses());
+      subchannelLogger = new ChannelLoggerImpl(subchannelTracer, timeProvider);
     }
 
     @Override
@@ -1465,12 +1475,6 @@ final class ManagedChannelImpl extends ManagedChannel implements
         }
       }
 
-      long subchannelCreationTime = timeProvider.currentTimeNanos();
-      InternalLogId subchannelLogId = InternalLogId.allocate("Subchannel", /*details=*/ null);
-      ChannelTracer subchannelTracer =
-          new ChannelTracer(
-              subchannelLogId, maxTraceEvents, subchannelCreationTime,
-              "Subchannel for " + args.getAddresses());
       InternalSubchannel internalSubchannel = new InternalSubchannel(
           args.getAddresses(),
           authority(),
@@ -1485,12 +1489,12 @@ final class ManagedChannelImpl extends ManagedChannel implements
           callTracerFactory.create(),
           subchannelTracer,
           subchannelLogId,
-          timeProvider);
+          subchannelLogger);
 
       channelTracer.reportEvent(new ChannelTrace.Event.Builder()
           .setDescription("Child Subchannel started")
           .setSeverity(ChannelTrace.Event.Severity.CT_INFO)
-          .setTimestampNanos(subchannelCreationTime)
+          .setTimestampNanos(timeProvider.currentTimeNanos())
           .setSubchannelRef(internalSubchannel)
           .build());
 
@@ -1586,11 +1590,12 @@ final class ManagedChannelImpl extends ManagedChannel implements
 
     @Override
     public String toString() {
-      return subchannel.getLogId().toString();
+      return subchannelLogId.toString();
     }
 
     @Override
     public Channel asChannel() {
+      checkState(started, "not started");
       return new SubchannelChannel(
           subchannel, balancerRpcExecutorHolder.getExecutor(),
           transportFactory.getScheduledExecutorService(),
@@ -1605,7 +1610,7 @@ final class ManagedChannelImpl extends ManagedChannel implements
 
     @Override
     public ChannelLogger getChannelLogger() {
-      return subchannel.getChannelLogger();
+      return subchannelLogger;
     }
   }
 

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

@@ -1274,13 +1274,16 @@ public class InternalSubchannelTest {
 
   private void createInternalSubchannel(EquivalentAddressGroup ... addrs) {
     List<EquivalentAddressGroup> addressGroups = Arrays.asList(addrs);
-    InternalLogId logId = InternalLogId.allocate("Subchannel", /*details=*/ null);
+    InternalLogId logId = InternalLogId.allocate("Subchannel", /*details=*/ AUTHORITY);
+    ChannelTracer subchannelTracer = new ChannelTracer(logId, 10,
+        fakeClock.getTimeProvider().currentTimeNanos(), "Subchannel");
     internalSubchannel = new InternalSubchannel(addressGroups, AUTHORITY, USER_AGENT,
         mockBackoffPolicyProvider, mockTransportFactory, fakeClock.getScheduledExecutorService(),
         fakeClock.getStopwatchSupplier(), syncContext, mockInternalSubchannelCallback,
         channelz, CallTracer.getDefaultFactory().create(),
-        new ChannelTracer(logId, 10, fakeClock.getTimeProvider().currentTimeNanos(), "Subchannel"),
-        logId, fakeClock.getTimeProvider());
+        subchannelTracer,
+        logId,
+        new ChannelLoggerImpl(subchannelTracer, fakeClock.getTimeProvider()));
   }
 
   private void assertNoCallbackInvoke() {

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

@@ -1328,6 +1328,20 @@ public class ManagedChannelImplTest {
     timer.forwardTime(ManagedChannelImpl.SUBCHANNEL_SHUTDOWN_DELAY_SECONDS, TimeUnit.SECONDS);
   }
 
+  @Test
+  public void subchannelStringableBeforeStart() {
+    createChannel();
+    Subchannel subchannel = createUnstartedSubchannel(helper, addressGroup, Attributes.EMPTY);
+    assertThat(subchannel.toString()).isNotNull();
+  }
+
+  @Test
+  public void subchannelLoggerCreatedBeforeSubchannelStarted() {
+    createChannel();
+    Subchannel subchannel = createUnstartedSubchannel(helper, addressGroup, Attributes.EMPTY);
+    assertThat(subchannel.getChannelLogger()).isNotNull();
+  }
+
   @Test
   public void subchannelsWhenChannelShutdownNow() {
     createChannel();
@@ -4001,6 +4015,23 @@ public class ManagedChannelImplTest {
     return resultCapture.get();
   }
 
+  private static Subchannel createUnstartedSubchannel(
+      final Helper helper, final EquivalentAddressGroup addressGroup, final Attributes attrs) {
+    final AtomicReference<Subchannel> resultCapture = new AtomicReference<>();
+    helper.getSynchronizationContext().execute(
+        new Runnable() {
+          @Override
+          public void run() {
+            Subchannel s = helper.createSubchannel(CreateSubchannelArgs.newBuilder()
+                .setAddresses(addressGroup)
+                .setAttributes(attrs)
+                .build());
+            resultCapture.set(s);
+          }
+        });
+    return resultCapture.get();
+  }
+
   private static void requestConnectionSafely(Helper helper, final Subchannel subchannel) {
     helper.getSynchronizationContext().execute(
         new Runnable() {