grpclb: remove redundant logs and add a system property to hide server lists in logs

The server list updates are very verbose and currently logged every second, causing a huge log spam if `ChannelLogger` is completely enabled. For debugging an internal issue, we need to turn on `ChannelLogger` but hide the server list updates from the logs to keep the log size reasonable.

grpclb/src/main/java/io/grpc/grpclb/GrpclbState.java

@@ -89,6 +89,11 @@ final class GrpclbState {
   private static final Attributes LB_PROVIDED_BACKEND_ATTRS =
       Attributes.newBuilder().set(GrpclbConstants.ATTR_LB_PROVIDED_BACKEND, true).build();
 
+  // Temporary workaround to reduce log spam for a grpclb server that incessantly sends updates
+  // Tracked by b/198440401
+  static final boolean SHOULD_LOG_SERVER_LISTS =
+      Boolean.parseBoolean(System.getProperty("io.grpc.grpclb.LogServerLists", "true"));
+
   @VisibleForTesting
   static final PickResult DROP_PICK_RESULT =
       PickResult.withDrop(Status.UNAVAILABLE.withDescription("Dropped as requested by balancer"));
@@ -469,12 +474,6 @@ final class GrpclbState {
   private void updateServerList(
       List<DropEntry> newDropList, List<BackendAddressGroup> newBackendAddrList,
       @Nullable GrpclbClientLoadRecorder loadRecorder) {
-    logger.log(
-        ChannelLogLevel.INFO,
-        "[grpclb-<{0}>] Using RR list={1}, drop={2}",
-        serviceName,
-        newBackendAddrList,
-        newDropList);
     HashMap<List<EquivalentAddressGroup>, Subchannel> newSubchannelMap =
         new HashMap<>();
     List<BackendEntry> newBackendList = new ArrayList<>();
@@ -710,9 +709,12 @@ final class GrpclbState {
         scheduleNextLoadReport();
         return;
       }
-
+      if (SHOULD_LOG_SERVER_LISTS) {
         logger.log(
             ChannelLogLevel.DEBUG, "[grpclb-<{0}>] Got an LB response: {1}", serviceName, response);
+      } else {
+        logger.log(ChannelLogLevel.DEBUG, "[grpclb-<{0}>] Got an LB response", serviceName);
+      }
 
       if (typeCase == LoadBalanceResponseTypeCase.FALLBACK_RESPONSE) {
         // Force entering fallback requested by balancer.
@@ -926,13 +928,6 @@ final class GrpclbState {
       return;
     }
     currentPicker = picker;
-    logger.log(
-        ChannelLogLevel.INFO,
-        "[grpclb-<{0}>] Update balancing state to {1}: picks={2}, drops={3}",
-        serviceName,
-        state,
-        picker.pickList,
-        picker.dropList);
     helper.updateBalancingState(state, picker);
   }
 
@@ -1179,10 +1174,13 @@ final class GrpclbState {
 
     @Override
     public String toString() {
+      if (SHOULD_LOG_SERVER_LISTS) {
         return MoreObjects.toStringHelper(RoundRobinPicker.class)
             .add("dropList", dropList)
             .add("pickList", pickList)
             .toString();
       }
+      return MoreObjects.toStringHelper(RoundRobinPicker.class).toString();
+    }
   }
 }

grpclb/src/test/java/io/grpc/grpclb/GrpclbLoadBalancerTest.java

@@ -794,12 +794,10 @@ public class GrpclbLoadBalancerTest {
     Status error = Status.NOT_FOUND.withDescription("www.google.com not found");
     deliverNameResolutionError(error);
     verify(helper).updateBalancingState(eq(TRANSIENT_FAILURE), pickerCaptor.capture());
-    assertThat(logs).containsExactly(
+    assertThat(logs)
+        .containsExactly(
             "INFO: [grpclb-<api.google.com>] Created",
-        "DEBUG: [grpclb-<api.google.com>] Error: " + error,
+            "DEBUG: [grpclb-<api.google.com>] Error: " + error)
-        "INFO: [grpclb-<api.google.com>] Update balancing state to TRANSIENT_FAILURE: picks="
-            + "[Status{code=UNAVAILABLE, description=www.google.com not found, cause=null}],"
-            + " drops=[]")
         .inOrder();
     logs.clear();
 
@@ -964,24 +962,13 @@ public class GrpclbLoadBalancerTest {
     inOrder.verifyNoMoreInteractions();
 
     assertThat(logs).containsExactly(
-            "DEBUG: [grpclb-<api.google.com>] Got an LB response: " + buildLbResponse(backends1),
+        "DEBUG: [grpclb-<api.google.com>] Got an LB response: " + buildLbResponse(backends1))
-            "INFO: [grpclb-<api.google.com>] Using RR list="
-                + "[[[/127.0.0.1:2000]/{io.grpc.grpclb.lbProvidedBackend=true}](token0001),"
-                + " [[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}](token0002)],"
-                + " drop=[null, null]",
-            "INFO: [grpclb-<api.google.com>]"
-                + " Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]")
         .inOrder();
     logs.clear();
 
     // Let subchannels be connected
     deliverSubchannelState(subchannel2, ConnectivityStateInfo.forNonError(READY));
     inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture());
-    assertThat(logs).containsExactly(
-        "INFO: [grpclb-<api.google.com>] Update balancing state to READY: picks="
-            + "[[[[[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0002)]],"
-            + " drops=[null, null]");
-    logs.clear();
 
     RoundRobinPicker picker1 = (RoundRobinPicker) pickerCaptor.getValue();
 
@@ -991,12 +978,6 @@ public class GrpclbLoadBalancerTest {
 
     deliverSubchannelState(subchannel1, ConnectivityStateInfo.forNonError(READY));
     inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture());
-    assertThat(logs).containsExactly(
-        "INFO: [grpclb-<api.google.com>] Update balancing state to READY: picks="
-            + "[[[[[/127.0.0.1:2000]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0001)],"
-            + " [[[[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0002)]],"
-            + " drops=[null, null]");
-    logs.clear();
 
     RoundRobinPicker picker2 = (RoundRobinPicker) pickerCaptor.getValue();
     assertThat(picker2.dropList).containsExactly(null, null);
@@ -1011,11 +992,6 @@ public class GrpclbLoadBalancerTest {
     verify(subchannel1, times(2)).requestConnection();
     inOrder.verify(helper).refreshNameResolution();
     inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture());
-    assertThat(logs).containsExactly(
-        "INFO: [grpclb-<api.google.com>] Update balancing state to READY: picks="
-            + "[[[[[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0002)]],"
-            + " drops=[null, null]");
-    logs.clear();
 
     RoundRobinPicker picker3 = (RoundRobinPicker) pickerCaptor.getValue();
     assertThat(picker3.dropList).containsExactly(null, null);
@@ -1037,10 +1013,6 @@ public class GrpclbLoadBalancerTest {
     deliverSubchannelState(subchannel2, ConnectivityStateInfo.forNonError(IDLE));
     verify(subchannel2, times(2)).requestConnection();
     inOrder.verify(helper).updateBalancingState(eq(CONNECTING), pickerCaptor.capture());
-    assertThat(logs).containsExactly(
-        "INFO: [grpclb-<api.google.com>] "
-            + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]");
-    logs.clear();
 
     RoundRobinPicker picker4 = (RoundRobinPicker) pickerCaptor.getValue();
     assertThat(picker4.dropList).containsExactly(null, null);
@@ -1059,15 +1031,7 @@ public class GrpclbLoadBalancerTest {
 
     lbResponseObserver.onNext(buildLbResponse(backends2));
     assertThat(logs).containsExactly(
-            "DEBUG: [grpclb-<api.google.com>] Got an LB response: " + buildLbResponse(backends2),
+        "DEBUG: [grpclb-<api.google.com>] Got an LB response: " + buildLbResponse(backends2))
-            "INFO: [grpclb-<api.google.com>] Using RR list="
-                + "[[[/127.0.0.1:2030]/{io.grpc.grpclb.lbProvidedBackend=true}](token0003),"
-                + " [[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}](token0004),"
-                + " [[/127.0.0.1:2030]/{io.grpc.grpclb.lbProvidedBackend=true}](token0005)],"
-                + " drop=[null, drop(token0003), null, null, drop(token0006)]",
-            "INFO: [grpclb-<api.google.com>]"
-                + " Update balancing state to CONNECTING: picks=[BUFFER_ENTRY],"
-                + " drops=[null, drop(token0003), null, null, drop(token0006)]")
         .inOrder();
     logs.clear();
 
@@ -1267,14 +1231,8 @@ public class GrpclbLoadBalancerTest {
       fakeClock.forwardTime(1, TimeUnit.MILLISECONDS);
 
       assertEquals(0, fakeClock.numPendingTasks(FALLBACK_MODE_TASK_FILTER));
-      assertThat(logs).containsExactly(
+      assertThat(logs)
-              "INFO: [grpclb-<api.google.com>] Using fallback backends",
+          .containsExactly("INFO: [grpclb-<api.google.com>] Using fallback backends")
-              "INFO: [grpclb-<api.google.com>]"
-                  + " Using RR list=[[[FakeSocketAddress-fake-address-0]/{}], "
-                  + "[[FakeSocketAddress-fake-address-1]/{}]], drop=[null, null]",
-              "INFO: [grpclb-<api.google.com>] "
-                  + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], "
-                  + "drops=[null, null]")
           .inOrder();
 
       // Fall back to the backends from resolver
@@ -1462,14 +1420,7 @@ public class GrpclbLoadBalancerTest {
     List<EquivalentAddressGroup> backendList = backends.subList(0, 2);
     deliverResolvedAddresses(backendList, Collections.<EquivalentAddressGroup>emptyList());
 
-    assertThat(logs).containsAtLeast(
+    assertThat(logs).contains("INFO: [grpclb-<api.google.com>] Using fallback backends");
-            "INFO: [grpclb-<api.google.com>] Using fallback backends",
-            "INFO: [grpclb-<api.google.com>] "
-                + "Using RR list=[[[FakeSocketAddress-fake-address-0]/{}], "
-                + "[[FakeSocketAddress-fake-address-1]/{}]], drop=[null, null]",
-            "INFO: [grpclb-<api.google.com>] "
-                + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]")
-        .inOrder();
 
     // Fall back to the backends from resolver
     fallbackTestVerifyUseOfFallbackBackendLists(inOrder, backendList);
@@ -1487,16 +1438,7 @@ public class GrpclbLoadBalancerTest {
     backendList = backends.subList(2, 5);
     deliverResolvedAddresses(backendList, Collections.<EquivalentAddressGroup>emptyList());
 
-    assertThat(logs).containsAtLeast(
+    assertThat(logs).contains("INFO: [grpclb-<api.google.com>] Using fallback backends");
-        "INFO: [grpclb-<api.google.com>] Using fallback backends",
-        "INFO: [grpclb-<api.google.com>] "
-            + "Using RR list=[[[FakeSocketAddress-fake-address-2]/{}], "
-            + "[[FakeSocketAddress-fake-address-3]/{}], "
-            + "[[FakeSocketAddress-fake-address-4]/{}]], drop=[null, null, null]",
-        "INFO: [grpclb-<api.google.com>] "
-            + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], "
-            + "drops=[null, null, null]")
-        .inOrder();
 
     // Shift to use updated backends
     fallbackTestVerifyUseOfFallbackBackendLists(inOrder, backendList);
@@ -2558,25 +2500,15 @@ public class GrpclbLoadBalancerTest {
     assertThat(picker0.pickList).containsExactly(BUFFER_ENTRY);
     inOrder.verifyNoMoreInteractions();
 
-    assertThat(logs).containsExactly(
+    assertThat(logs)
-            "DEBUG: [grpclb-<api.google.com>] Got an LB response: " + buildLbResponse(backends1),
+        .containsExactly(
-            "INFO: [grpclb-<api.google.com>] Using RR list="
+            "DEBUG: [grpclb-<api.google.com>] Got an LB response: " + buildLbResponse(backends1))
-                + "[[[/127.0.0.1:2000]/{io.grpc.grpclb.lbProvidedBackend=true}](token0001),"
-                + " [[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}](token0002)],"
-                + " drop=[null, null]",
-            "INFO: [grpclb-<api.google.com>] "
-                + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]")
         .inOrder();
     logs.clear();
 
     // Let subchannels be connected
     deliverSubchannelState(subchannel2, ConnectivityStateInfo.forNonError(READY));
     inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture());
-    assertThat(logs).containsExactly(
-        "INFO: [grpclb-<api.google.com>] Update balancing state to READY: picks="
-            + "[[[[[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0002)]],"
-            + " drops=[null, null]");
-    logs.clear();
 
     RoundRobinPicker picker1 = (RoundRobinPicker) pickerCaptor.getValue();
 
@@ -2586,12 +2518,6 @@ public class GrpclbLoadBalancerTest {
 
     deliverSubchannelState(subchannel1, ConnectivityStateInfo.forNonError(READY));
     inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture());
-    assertThat(logs).containsExactly(
-        "INFO: [grpclb-<api.google.com>] Update balancing state to READY: picks="
-            + "[[[[[/127.0.0.1:2000]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0001)],"
-            + " [[[[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0002)]],"
-            + " drops=[null, null]");
-    logs.clear();
 
     RoundRobinPicker picker2 = (RoundRobinPicker) pickerCaptor.getValue();
     assertThat(picker2.dropList).containsExactly(null, null);
@@ -2672,25 +2598,15 @@ public class GrpclbLoadBalancerTest {
     assertThat(picker6.pickList).containsExactly(BUFFER_ENTRY);
     inOrder.verifyNoMoreInteractions();
 
-    assertThat(logs).containsExactly(
+    assertThat(logs)
-            "DEBUG: [grpclb-<api.google.com>] Got an LB response: " + buildLbResponse(backends2),
+        .containsExactly(
-            "INFO: [grpclb-<api.google.com>] Using RR list="
+            "DEBUG: [grpclb-<api.google.com>] Got an LB response: " + buildLbResponse(backends2))
-                + "[[[/127.0.0.1:8000]/{io.grpc.grpclb.lbProvidedBackend=true}](token1001),"
-                + " [[/127.0.0.1:8010]/{io.grpc.grpclb.lbProvidedBackend=true}](token1002)],"
-                + " drop=[null, null]",
-            "INFO: [grpclb-<api.google.com>] "
-                + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]")
         .inOrder();
     logs.clear();
 
     // Let new subchannels be connected
     deliverSubchannelState(subchannel3, ConnectivityStateInfo.forNonError(READY));
     inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture());
-    assertThat(logs).containsExactly(
-        "INFO: [grpclb-<api.google.com>] Update balancing state to READY: picks="
-            + "[[[[[/127.0.0.1:8000]/{io.grpc.grpclb.lbProvidedBackend=true}]](token1001)]],"
-            + " drops=[null, null]");
-    logs.clear();
 
     RoundRobinPicker picker3 = (RoundRobinPicker) pickerCaptor.getValue();
     assertThat(picker3.dropList).containsExactly(null, null);
@@ -2699,12 +2615,6 @@ public class GrpclbLoadBalancerTest {
 
     deliverSubchannelState(subchannel4, ConnectivityStateInfo.forNonError(READY));
     inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture());
-    assertThat(logs).containsExactly(
-        "INFO: [grpclb-<api.google.com>] Update balancing state to READY: picks="
-            + "[[[[[/127.0.0.1:8000]/{io.grpc.grpclb.lbProvidedBackend=true}]](token1001)],"
-            + " [[[[/127.0.0.1:8010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token1002)]],"
-            + " drops=[null, null]");
-    logs.clear();
 
     RoundRobinPicker picker4 = (RoundRobinPicker) pickerCaptor.getValue();
     assertThat(picker4.dropList).containsExactly(null, null);