core: DelayedClientCall should include context in error

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