xds: error descriptions improvements(#8554)

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

@@ -179,7 +179,8 @@ private void handleClusterDiscovered() {
           childLb = null;
         }
         Status unavailable =
-            Status.UNAVAILABLE.withDescription("Cluster " + root.name + " unusable");
+            Status.UNAVAILABLE.withDescription("CDS error: found 0 leaf (logical DNS or EDS) "
+                + "clusters for root cluster " + root.name);
         helper.updateBalancingState(TRANSIENT_FAILURE, new ErrorPicker(unavailable));
         return;
       }

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

@@ -566,7 +566,8 @@ private static void checkForUniqueness(Set<FilterChainMatch> uniqueSet,
       List<FilterChainMatch> crossProduct = getCrossProduct(filterChainMatch);
       for (FilterChainMatch cur : crossProduct) {
         if (!uniqueSet.add(cur)) {
-          throw new ResourceInvalidException("Found duplicate matcher: " + cur);
+          throw new ResourceInvalidException("FilterChainMatch must be unique. "
+              + "Found duplicate: " + cur);
         }
       }
     }

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

@@ -124,7 +124,9 @@ public void handleResolvedAddresses(ResolvedAddresses resolvedAddresses) {
         if (config.lrsServerName.isEmpty()) {
           dropStats = xdsClient.addClusterDropStats(cluster, edsServiceName);
         } else {
-          logger.log(XdsLogLevel.WARNING, "Can only report load to the same management server");
+          logger.log(XdsLogLevel.WARNING, "Cluster {0} config error: can only report load "
+              + "to the same management server. Config lrsServerName {1} should be empty. ",
+              cluster, config.lrsServerName);
         }
       }
     }

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

@@ -149,7 +149,8 @@ public PickResult pickSubchannel(PickSubchannelArgs args) {
           if (delegate == null) {
             return
                 PickResult.withError(
-                    Status.UNAVAILABLE.withDescription("Unable to find cluster " + clusterName));
+                    Status.UNAVAILABLE.withDescription("CDS encountered error: unable to find "
+                        + "available subchannel for cluster " + clusterName));
           }
           return delegate.pickSubchannel(args);
         }

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

@@ -501,7 +501,8 @@ void start() {
         }
         resolver = nameResolverFactory.newNameResolver(uri, nameResolverArgs);
         if (resolver == null) {
-          status = Status.INTERNAL.withDescription("Cannot find DNS resolver");
+          status = Status.INTERNAL.withDescription("Xds cluster resolver lb for logical DNS "
+              + "cluster [" + name + "] cannot find DNS resolver with uri:" + uri);
           handleEndpointResolutionError();
           return;
         }
@@ -607,7 +608,9 @@ public void run() {
               }
               long delayNanos = backoffPolicy.nextBackoffNanos();
               logger.log(XdsLogLevel.DEBUG,
-                  "Scheduling DNS resolution backoff for {0} ns", delayNanos);
+                  "Logical DNS resolver for cluster {0} encountered name resolution "
+                      + "error: {1}, scheduling DNS resolution backoff for {2} ns",
+                  name, error, delayNanos);
               scheduledRefresh =
                   syncContext.schedule(
                       new DelayedNameResolverRefresh(), delayNanos, TimeUnit.NANOSECONDS,

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

@@ -23,6 +23,7 @@
 import static io.grpc.xds.internal.sds.SdsProtocolNegotiators.ATTR_SERVER_SSL_CONTEXT_PROVIDER_SUPPLIER;
 
 import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.MoreObjects;
 import com.google.common.base.Strings;
 import com.google.common.collect.Iterables;
 import com.google.protobuf.UInt32Value;
@@ -141,12 +142,11 @@ static final class FilterChainSelector {
       private final Map<FilterChain, AtomicReference<ServerRoutingConfig>> routingConfigs;
       @Nullable
       private final SslContextProviderSupplier defaultSslContextProviderSupplier;
-      @Nullable
       private final AtomicReference<ServerRoutingConfig> defaultRoutingConfig;
 
       FilterChainSelector(Map<FilterChain, AtomicReference<ServerRoutingConfig>> routingConfigs,
                           @Nullable SslContextProviderSupplier defaultSslContextProviderSupplier,
-                          @Nullable AtomicReference<ServerRoutingConfig> defaultRoutingConfig) {
+                          AtomicReference<ServerRoutingConfig> defaultRoutingConfig) {
         this.routingConfigs = checkNotNull(routingConfigs, "routingConfigs");
         this.defaultSslContextProviderSupplier = defaultSslContextProviderSupplier;
         this.defaultRoutingConfig = checkNotNull(defaultRoutingConfig, "defaultRoutingConfig");
@@ -350,6 +350,15 @@ private static Collection<FilterChain> filterOnIpAddress(
         }
         return topOnes;
       }
+
+      @Override
+      public String toString() {
+        return MoreObjects.toStringHelper(this)
+            .add("routingConfigs", routingConfigs)
+            .add("defaultSslContextProviderSupplier", defaultSslContextProviderSupplier)
+            .add("defaultRoutingConfig", defaultRoutingConfig)
+            .toString();
+      }
     }
   }
 

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

@@ -177,9 +177,11 @@ public <ReqT, RespT> ServerCall.Listener<ReqT> interceptCall(
                 final ServerCall<ReqT, RespT> call,
                 final Metadata headers, ServerCallHandler<ReqT, RespT> next) {
           AuthDecision authResult = authEngine.evaluate(headers, call);
-          logger.log(Level.FINE,
-                  "Authorization result for serverCall {0}: {1}, matching policy: {2}.",
-                  new Object[]{call, authResult.decision(), authResult.matchingPolicyName()});
+          if (logger.isLoggable(Level.FINER)) {
+            logger.log(Level.FINER,
+                "Authorization result for serverCall {0}: {1}, matching policy: {2}.",
+                new Object[]{call, authResult.decision(), authResult.matchingPolicyName()});
+          }
           if (GrpcAuthorizationEngine.Action.DENY.equals(authResult.decision())) {
             Status status = Status.UNAUTHENTICATED.withDescription(
                     "Access Denied, matching policy: " + authResult.matchingPolicyName());

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

@@ -56,7 +56,8 @@ final class RingHashLoadBalancer extends LoadBalancer {
   private static final Attributes.Key<Ref<ConnectivityStateInfo>> STATE_INFO =
       Attributes.Key.create("state-info");
   private static final Status RPC_HASH_NOT_FOUND =
-      Status.INTERNAL.withDescription("RPC hash not found");
+      Status.INTERNAL.withDescription("RPC hash not found. Probably a bug because xds resolver"
+          + " config selector always generates a hash.");
   private static final XxHash64 hashFunc = XxHash64.INSTANCE;
 
   private final XdsLogger logger;
@@ -79,7 +80,8 @@ public void handleResolvedAddresses(ResolvedAddresses resolvedAddresses) {
     logger.log(XdsLogLevel.DEBUG, "Received resolution result: {0}", resolvedAddresses);
     List<EquivalentAddressGroup> addrList = resolvedAddresses.getAddresses();
     if (addrList.isEmpty()) {
-      handleNameResolutionError(Status.UNAVAILABLE.withDescription("No server addresses found"));
+      handleNameResolutionError(Status.UNAVAILABLE.withDescription("Ring hash lb error: EDS "
+          + "resolution was successful, but returned server addresses are empty."));
       return;
     }
     Map<EquivalentAddressGroup, EquivalentAddressGroup> latestAddrs = stripAttrs(addrList);

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

@@ -318,6 +318,7 @@ private void startDelegateServer() {
         initialStarted = true;
         initialStartFuture.set(null);
       }
+      logger.log(Level.FINER, "Delegate server started.");
     } catch (IOException e) {
       logger.log(Level.FINE, "Fail to start delegate server: {0}", e);
       if (!initialStarted) {
@@ -371,6 +372,7 @@ public void run() {
           if (stopped) {
             return;
           }
+          logger.log(Level.FINEST, "Received Lds update {0}", update);
           checkNotNull(update.listener(), "update");
           if (!pendingRds.isEmpty()) {
             // filter chain state has not yet been applied to filterChainSelectorManager and there
@@ -474,6 +476,7 @@ private void updateSelector() {
           defaultFilterChain == null ? new AtomicReference<ServerRoutingConfig>() :
               generateRoutingConfig(defaultFilterChain));
       List<SslContextProviderSupplier> toRelease = getSuppliersInUse();
+      logger.log(Level.FINEST, "Updating selector {0}", selector);
       filterChainSelectorManager.updateSelector(selector);
       for (SslContextProviderSupplier e: toRelease) {
         e.close();
@@ -696,6 +699,8 @@ private void updateRdsRoutingConfig() {
               updatedRoutingConfig = ServerRoutingConfig.create(savedVirtualHosts,
                   updatedInterceptors);
             }
+            logger.log(Level.FINEST, "Updating filter chain {0} rds routing config: {1}",
+                new Object[]{filterChain.getName(), updatedRoutingConfig});
             savedRdsRoutingConfigRef.get(filterChain).set(updatedRoutingConfig);
           }
         }

xds/src/main/java/io/grpc/xds/internal/rbac/engine/GrpcAuthorizationEngine.java

@@ -78,8 +78,6 @@ public AuthDecision evaluate(Metadata metadata, ServerCall<?,?> serverCall) {
     if (Action.DENY.equals(authConfig.action()) == (firstMatch == null)) {
       decisionType = Action.ALLOW;
     }
-    log.log(Level.FINER, "RBAC decision: {0}, policy match: {1}.",
-            new Object[]{decisionType, firstMatch});
     return AuthDecision.create(decisionType, firstMatch);
   }
 

xds/src/main/java/io/grpc/xds/internal/sds/SdsProtocolNegotiators.java

@@ -281,11 +281,16 @@ public void userEventTriggered(ChannelHandlerContext ctx, Object evt) throws Exc
         SslContextProviderSupplier sslContextProviderSupplier = InternalProtocolNegotiationEvent
                 .getAttributes(pne).get(ATTR_SERVER_SSL_CONTEXT_PROVIDER_SUPPLIER);
         if (sslContextProviderSupplier == null) {
+          logger.log(Level.FINE, "No sslContextProviderSupplier found in filterChainMatch "
+              + "for connection from {0} to {1}",
+              new Object[]{ctx.channel().remoteAddress(), ctx.channel().localAddress()});
           if (fallbackProtocolNegotiator == null) {
             ctx.fireExceptionCaught(new CertStoreException("No certificate source found!"));
             return;
           }
-          logger.log(Level.INFO, "Using fallback for {0}", ctx.channel().localAddress());
+          logger.log(Level.FINE, "Using fallback sslContextProviderSupplier for connection "
+              + "from {0} to {1}",
+              new Object[]{ctx.channel().remoteAddress(), ctx.channel().localAddress()});
           ctx.pipeline()
               .replace(
                   this,

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

@@ -179,7 +179,8 @@ public void nonAggregateCluster_resourceNotExist_returnErrorPicker() {
     xdsClient.deliverResourceNotExist(CLUSTER);
     verify(helper).updateBalancingState(
         eq(ConnectivityState.TRANSIENT_FAILURE), pickerCaptor.capture());
-    Status unavailable = Status.UNAVAILABLE.withDescription("Cluster " + CLUSTER + " unusable");
+    Status unavailable = Status.UNAVAILABLE.withDescription(
+        "CDS error: found 0 leaf (logical DNS or EDS) clusters for root cluster " + CLUSTER);
     assertPicker(pickerCaptor.getValue(), unavailable, null);
     assertThat(childBalancers).isEmpty();
   }
@@ -221,7 +222,8 @@ public void nonAggregateCluster_resourceRevoked() {
 
     xdsClient.deliverResourceNotExist(CLUSTER);
     assertThat(childBalancer.shutdown).isTrue();
-    Status unavailable = Status.UNAVAILABLE.withDescription("Cluster " + CLUSTER + " unusable");
+    Status unavailable = Status.UNAVAILABLE.withDescription(
+        "CDS error: found 0 leaf (logical DNS or EDS) clusters for root cluster " + CLUSTER);
     verify(helper).updateBalancingState(
         eq(ConnectivityState.TRANSIENT_FAILURE), pickerCaptor.capture());
     assertPicker(pickerCaptor.getValue(), unavailable, null);
@@ -295,7 +297,8 @@ public void aggregateCluster_noNonAggregateClusterExits_returnErrorPicker() {
     xdsClient.deliverResourceNotExist(cluster1);
     verify(helper).updateBalancingState(
         eq(ConnectivityState.TRANSIENT_FAILURE), pickerCaptor.capture());
-    Status unavailable = Status.UNAVAILABLE.withDescription("Cluster " + CLUSTER + " unusable");
+    Status unavailable = Status.UNAVAILABLE.withDescription(
+        "CDS error: found 0 leaf (logical DNS or EDS) clusters for root cluster " + CLUSTER);
     assertPicker(pickerCaptor.getValue(), unavailable, null);
     assertThat(childBalancers).isEmpty();
   }
@@ -341,7 +344,8 @@ public void aggregateCluster_descendantClustersRevoked() {
     xdsClient.deliverResourceNotExist(cluster2);
     verify(helper).updateBalancingState(
         eq(ConnectivityState.TRANSIENT_FAILURE), pickerCaptor.capture());
-    Status unavailable = Status.UNAVAILABLE.withDescription("Cluster " + CLUSTER + " unusable");
+    Status unavailable = Status.UNAVAILABLE.withDescription(
+        "CDS error: found 0 leaf (logical DNS or EDS) clusters for root cluster " + CLUSTER);
     assertPicker(pickerCaptor.getValue(), unavailable, null);
     assertThat(childBalancer.shutdown).isTrue();
     assertThat(childBalancers).isEmpty();
@@ -379,7 +383,8 @@ public void aggregateCluster_rootClusterRevoked() {
         .containsExactly(CLUSTER);  // subscription to all descendant clusters cancelled
     verify(helper).updateBalancingState(
         eq(ConnectivityState.TRANSIENT_FAILURE), pickerCaptor.capture());
-    Status unavailable = Status.UNAVAILABLE.withDescription("Cluster " + CLUSTER + " unusable");
+    Status unavailable = Status.UNAVAILABLE.withDescription(
+        "CDS error: found 0 leaf (logical DNS or EDS) clusters for root cluster " + CLUSTER);
     assertPicker(pickerCaptor.getValue(), unavailable, null);
     assertThat(childBalancer.shutdown).isTrue();
     assertThat(childBalancers).isEmpty();
@@ -427,7 +432,8 @@ public void aggregateCluster_intermediateClusterChanges() {
         .containsExactly(CLUSTER, cluster2);  // cancelled subscription to cluster3
     verify(helper).updateBalancingState(
         eq(ConnectivityState.TRANSIENT_FAILURE), pickerCaptor.capture());
-    Status unavailable = Status.UNAVAILABLE.withDescription("Cluster " + CLUSTER + " unusable");
+    Status unavailable = Status.UNAVAILABLE.withDescription(
+        "CDS error: found 0 leaf (logical DNS or EDS) clusters for root cluster " + CLUSTER);
     assertPicker(pickerCaptor.getValue(), unavailable, null);
     assertThat(childBalancer.shutdown).isTrue();
     assertThat(childBalancers).isEmpty();

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

@@ -1407,7 +1407,7 @@ public void parseServerSideListener_nonUniqueFilterChainMatch() throws ResourceI
             .addAllFilterChains(Arrays.asList(filterChain1, filterChain2))
             .build();
     thrown.expect(ResourceInvalidException.class);
-    thrown.expectMessage("Found duplicate matcher:");
+    thrown.expectMessage("FilterChainMatch must be unique. Found duplicate:");
     ClientXdsClient.parseServerSideListener(
         listener, new HashSet<String>(), null, filterRegistry, null, true /* does not matter */);
   }
@@ -1456,7 +1456,7 @@ public void parseServerSideListener_nonUniqueFilterChainMatch_sameFilter()
             .addAllFilterChains(Arrays.asList(filterChain1, filterChain2))
             .build();
     thrown.expect(ResourceInvalidException.class);
-    thrown.expectMessage("Found duplicate matcher:");
+    thrown.expectMessage("FilterChainMatch must be unique. Found duplicate:");
     ClientXdsClient.parseServerSideListener(
         listener, new HashSet<String>(), null, filterRegistry, null, true /* does not matter */);
   }

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

@@ -138,7 +138,8 @@ public void handleResolvedAddressesUpdatesChannelPicker() {
     assertThat(pickSubchannel(picker, "childC")).isEqualTo(PickResult.withNoResult());
     Status status = pickSubchannel(picker, "childB").getStatus();
     assertThat(status.getCode()).isEqualTo(Code.UNAVAILABLE);
-    assertThat(status.getDescription()).isEqualTo("Unable to find cluster childB");
+    assertThat(status.getDescription()).isEqualTo(
+        "CDS encountered error: unable to find available subchannel for cluster childB");
     assertThat(fakeClock.numPendingTasks())
         .isEqualTo(1);  // (delayed) shutdown because "childB" is removed
     assertThat(childBalancer1.shutdown).isFalse();