core: DelayedClientCall should include context in error

If the RPC is able to continue in time it can proceed to ClientCallImpl,
which will describe the delay as coming from name resolution. But if it
fails before then the message didn't give any hint what gRPC was waiting
on.

As noticed during b/526868988.

Author: ejona86

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

@@ -49,6 +49,9 @@
  */
 public class DelayedClientCall<ReqT, RespT> extends ClientCall<ReqT, RespT> {
   private static final Logger logger = Logger.getLogger(DelayedClientCall.class.getName());
+
+  /** A string describing what this call is waiting on. */
+  private final String bufferContext;
   /**
    * A timer to monitor the initial deadline. The timer must be cancelled on transition to the real
    * call.
@@ -76,7 +79,11 @@ public class DelayedClientCall<ReqT, RespT> extends ClientCall<ReqT, RespT> {
   private DelayedListener<RespT> delayedListener;
 
   protected DelayedClientCall(
-      Executor callExecutor, ScheduledExecutorService scheduler, @Nullable Deadline deadline) {
+      String bufferContext,
+      Executor callExecutor,
+      ScheduledExecutorService scheduler,
+      @Nullable Deadline deadline) {
+    this.bufferContext = checkNotNull(bufferContext, "bufferContext");
     this.callExecutor = checkNotNull(callExecutor, "callExecutor");
     checkNotNull(scheduler, "scheduler");
     context = Context.current();
@@ -143,7 +150,8 @@ public void run() {
         }
         buf.append(seconds);
         buf.append(String.format(Locale.US, ".%09d", nanos));
-        buf.append("s");
+        buf.append("s waiting for ");
+        buf.append(bufferContext);
         cancel(
             Status.DEADLINE_EXCEEDED.withDescription(buf.toString()),
             // We should not cancel the call if the realCall is set because there could be a

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

@@ -986,9 +986,12 @@ private final class PendingCall<ReqT, RespT> extends DelayedClientCall<ReqT, Res
       final CallOptions callOptions;
       private final long callCreationTime;
 
-      PendingCall(
-          Context context, MethodDescriptor<ReqT, RespT> method, CallOptions callOptions) {
-        super(getCallExecutor(callOptions), scheduledExecutor, callOptions.getDeadline());
+      PendingCall(Context context, MethodDescriptor<ReqT, RespT> method, CallOptions callOptions) {
+        super(
+            "name_resolver",
+            getCallExecutor(callOptions),
+            scheduledExecutor,
+            callOptions.getDeadline());
         this.context = context;
         this.method = method;
         this.callOptions = callOptions;

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

@@ -66,8 +66,8 @@ public class DelayedClientCallTest {
 
   @Test
   public void allMethodsForwarded() throws Exception {
-    DelayedClientCall<String, Integer> delayedClientCall =
-        new DelayedClientCall<>(callExecutor, fakeClock.getScheduledExecutorService(), null);
+    DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     callMeMaybe(delayedClientCall.setCall(mockRealCall));
     ForwardingTestUtil.testMethodsForwarded(
         ClientCall.class,
@@ -94,18 +94,22 @@ public Object get(Method method, int argPos, Class<?> clazz) {
   @Test
   public void deadlineExceededWhileCallIsStartedButStillPending() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), Deadline.after(10, SECONDS));
+        "tESt", callExecutor, fakeClock.getScheduledExecutorService(),
+        Deadline.after(10, SECONDS, fakeClock.getDeadlineTicker()));
 
     delayedClientCall.start(listener, new Metadata());
     fakeClock.forwardTime(10, SECONDS);
     verify(listener).onClose(statusCaptor.capture(), any(Metadata.class));
     assertThat(statusCaptor.getValue().getCode()).isEqualTo(Status.Code.DEADLINE_EXCEEDED);
+    assertThat(statusCaptor.getValue().getDescription())
+        .isEqualTo("Deadline CallOptions was exceeded after 10.000000000s waiting for tESt");
   }
 
   @Test
   public void listenerEventsPropagated() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), Deadline.after(10, SECONDS));
+        "test", callExecutor, fakeClock.getScheduledExecutorService(),
+        Deadline.after(10, SECONDS, fakeClock.getDeadlineTicker()));
     delayedClientCall.start(listener, new Metadata());
     callMeMaybe(delayedClientCall.setCall(mockRealCall));
     @SuppressWarnings("unchecked")
@@ -130,7 +134,7 @@ public void listenerEventsPropagated() {
   @Test
   public void setCallThenStart() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     callMeMaybe(delayedClientCall.setCall(mockRealCall));
     delayedClientCall.start(listener, new Metadata());
     delayedClientCall.request(1);
@@ -146,7 +150,7 @@ public void setCallThenStart() {
   @Test
   public void startThenSetCall() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     delayedClientCall.start(listener, new Metadata());
     delayedClientCall.request(1);
     Runnable r = delayedClientCall.setCall(mockRealCall);
@@ -167,7 +171,7 @@ public void startThenSetCall() {
   @SuppressWarnings("unchecked")
   public void cancelThenSetCall() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     delayedClientCall.start(listener, new Metadata());
     delayedClientCall.request(1);
     delayedClientCall.cancel("cancel", new StatusException(Status.CANCELLED));
@@ -183,7 +187,7 @@ public void cancelThenSetCall() {
   @SuppressWarnings("unchecked")
   public void setCallThenCancel() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     delayedClientCall.start(listener, new Metadata());
     delayedClientCall.request(1);
     Runnable r = delayedClientCall.setCall(mockRealCall);
@@ -206,7 +210,8 @@ public void delayedCallsRunUnderContext() throws Exception {
     Object goldenValue = new Object();
     DelayedClientCall<String, Integer> delayedClientCall =
         Context.current().withValue(contextKey, goldenValue).call(() ->
-            new DelayedClientCall<>(callExecutor, fakeClock.getScheduledExecutorService(), null));
+            new DelayedClientCall<>(
+                "test", callExecutor, fakeClock.getScheduledExecutorService(), null));
     AtomicReference<Context> readyContext = new AtomicReference<>();
     delayedClientCall.start(new ClientCall.Listener<Integer>() {
       @Override public void onReady() {
@@ -232,7 +237,7 @@ public void delayedCallsRunUnderContext() throws Exception {
   @Test
   public void listenerThrowsInPendingCallback_cancelsRealCall() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     final RuntimeException boom = new RuntimeException("boom");
     ClientCall.Listener<Integer> throwingListener = new ClientCall.Listener<Integer>() {
       @Override
@@ -261,7 +266,7 @@ public void start(Listener<Integer> listener, Metadata metadata) {
   @Test
   public void listenerThrowsInPendingOnHeaders_cancelsRealCall() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     final RuntimeException boom = new RuntimeException("boom");
     ClientCall.Listener<Integer> throwingListener = new ClientCall.Listener<Integer>() {
       @Override
@@ -286,7 +291,7 @@ public void start(Listener<Integer> listener, Metadata metadata) {
   @Test
   public void listenerThrowsInPendingOnReady_cancelsRealCall() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     final RuntimeException boom = new RuntimeException("boom");
     ClientCall.Listener<Integer> throwingListener = new ClientCall.Listener<Integer>() {
       @Override
@@ -311,7 +316,7 @@ public void start(Listener<Integer> listener, Metadata metadata) {
   @Test
   public void onCloseExceptionCaughtAndLogged() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     final RuntimeException boom = new RuntimeException("boom");
     final AtomicReference<Status> observed = new AtomicReference<>();
     ClientCall.Listener<Integer> throwingListener = new ClientCall.Listener<Integer>() {
@@ -339,7 +344,7 @@ public void start(Listener<Integer> listener, Metadata metadata) {
   @Test
   public void listenerThrowsInPassThroughOnMessage_cancelsRealCall() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     final RuntimeException boom = new RuntimeException("boom");
     ClientCall.Listener<Integer> throwingListener = new ClientCall.Listener<Integer>() {
       @Override
@@ -362,7 +367,7 @@ public void onMessage(Integer msg) {
   @Test
   public void listenerThrowsInPassThroughOnHeaders_cancelsRealCall() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     final RuntimeException boom = new RuntimeException("boom");
     ClientCall.Listener<Integer> throwingListener = new ClientCall.Listener<Integer>() {
       @Override
@@ -385,7 +390,7 @@ public void onHeaders(Metadata headers) {
   @Test
   public void listenerThrowsInPassThroughOnReady_cancelsRealCall() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     final RuntimeException boom = new RuntimeException("boom");
     ClientCall.Listener<Integer> throwingListener = new ClientCall.Listener<Integer>() {
       @Override
@@ -408,7 +413,7 @@ public void onReady() {
   @Test
   public void listenerThrowsInPassThrough_subsequentCallbacksSwallowedAndOnCloseOverridden() {
     DelayedClientCall<String, Integer> delayedClientCall = new DelayedClientCall<>(
-        callExecutor, fakeClock.getScheduledExecutorService(), null);
+        "test", callExecutor, fakeClock.getScheduledExecutorService(), null);
     final RuntimeException boom = new RuntimeException("boom");
     final AtomicReference<Integer> lastMessage = new AtomicReference<>();
     final AtomicReference<Status> closeStatus = new AtomicReference<>();

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

@@ -397,7 +397,7 @@ private static String getHeaderValue(Metadata headers, String headerName) {
   private static class DataPlaneDelayedCall<ReqT, RespT> extends DelayedClientCall<ReqT, RespT> {
     DataPlaneDelayedCall(
         Executor executor, ScheduledExecutorService scheduler, @Nullable Deadline deadline) {
-      super(executor, scheduler, deadline);
+      super("ext_proc", executor, scheduler, deadline);
     }
   }
 

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

@@ -414,7 +414,7 @@ private final class DelayInjectedCall<ReqT, RespT> extends DelayedClientCall<Req
         long delayNanos, Executor callExecutor, ScheduledExecutorService scheduler,
         @Nullable Deadline deadline,
         final Supplier<? extends ClientCall<ReqT, RespT>> callSupplier) {
-      super(callExecutor, scheduler, deadline);
+      super("httpfault_filter", callExecutor, scheduler, deadline);
       activeFaultCounter.incrementAndGet();
       ScheduledFuture<?> task = scheduler.schedule(
           new Runnable() {

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

@@ -2339,7 +2339,7 @@ public long nanoTime() {
     assertThat(testCall).isNull();
     verifyRpcDelayedThenAborted(observer, 4000L, Status.DEADLINE_EXCEEDED.withDescription(
         "Deadline exceeded after up to 5000 ns of fault-injected delay:"
-            + " Deadline CallOptions was exceeded after 0.000004000s"));
+        + " Deadline CallOptions was exceeded after 0.000004000s waiting for httpfault_filter"));
   }
 
   @Test