Improve error message when deadline is exceeded, making it clear which deadline (Context or CallOptions) was exceeded and making the grammar clearer. (#9713)

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

@@ -72,6 +72,7 @@ final class ClientCallImpl<ReqT, RespT> extends ClientCall<ReqT, RespT> {
   private static final Logger log = Logger.getLogger(ClientCallImpl.class.getName());
   private static final byte[] FULL_STREAM_DECOMPRESSION_ENCODINGS
       = "gzip".getBytes(Charset.forName("US-ASCII"));
+  private static final double NANO_TO_SECS = 1.0 * TimeUnit.SECONDS.toNanos(1);
 
   private final MethodDescriptor<ReqT, RespT> method;
   private final Tag tag;
@@ -259,10 +260,12 @@ final class ClientCallImpl<ReqT, RespT> extends ClientCall<ReqT, RespT> {
     } else {
       ClientStreamTracer[] tracers =
           GrpcUtil.getClientStreamTracers(callOptions, headers, 0, false);
-      stream = new FailingClientStream(
+      String deadlineName =
-          DEADLINE_EXCEEDED.withDescription(
+          isFirstMin(callOptions.getDeadline(), context.getDeadline()) ? "CallOptions" : "Context";
-              "ClientCall started after deadline exceeded: " + effectiveDeadline),
+      String description = String.format(
-          tracers);
+          "ClientCall started after %s deadline was exceeded .9%f seconds ago", deadlineName,
+          effectiveDeadline.timeRemaining(TimeUnit.NANOSECONDS) / NANO_TO_SECS);
+      stream = new FailingClientStream(DEADLINE_EXCEEDED.withDescription(description), tracers);
     }
 
     if (callExecutorIsDirect) {
@@ -431,6 +434,16 @@ final class ClientCallImpl<ReqT, RespT> extends ClientCall<ReqT, RespT> {
     return deadline0.minimum(deadline1);
   }
 
+  private static boolean isFirstMin(@Nullable Deadline deadline0, @Nullable Deadline deadline1) {
+    if (deadline0 == null) {
+      return false;
+    }
+    if (deadline1 == null) {
+      return true;
+    }
+    return deadline0.isBefore(deadline1);
+  }
+
   @Override
   public void request(int numMessages) {
     PerfMark.startTask("ClientCall.request", tag);

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

@@ -81,6 +81,17 @@ public class DelayedClientCall<ReqT, RespT> extends ClientCall<ReqT, RespT> {
     initialDeadlineMonitor = scheduleDeadlineIfNeeded(scheduler, deadline);
   }
 
+  // If one argument is null, consider the other the "Before"
+  private boolean isAbeforeB(@Nullable Deadline a, @Nullable Deadline b) {
+    if (b == null) {
+      return true;
+    } else if (a == null) {
+      return false;
+    }
+
+    return a.isBefore(b);
+  }
+
   @Nullable
   private ScheduledFuture<?> scheduleDeadlineIfNeeded(
       ScheduledExecutorService scheduler, @Nullable Deadline deadline) {
@@ -90,8 +101,9 @@ public class DelayedClientCall<ReqT, RespT> extends ClientCall<ReqT, RespT> {
     }
     long remainingNanos = Long.MAX_VALUE;
     if (deadline != null) {
-      remainingNanos = Math.min(remainingNanos, deadline.timeRemaining(NANOSECONDS));
+      remainingNanos = deadline.timeRemaining(NANOSECONDS);
     }
+
     if (contextDeadline != null && contextDeadline.timeRemaining(NANOSECONDS) < remainingNanos) {
       remainingNanos = contextDeadline.timeRemaining(NANOSECONDS);
       if (logger.isLoggable(Level.FINE)) {
@@ -110,13 +122,19 @@ public class DelayedClientCall<ReqT, RespT> extends ClientCall<ReqT, RespT> {
         logger.fine(builder.toString());
       }
     }
+
     long seconds = Math.abs(remainingNanos) / TimeUnit.SECONDS.toNanos(1);
     long nanos = Math.abs(remainingNanos) % TimeUnit.SECONDS.toNanos(1);
     final StringBuilder buf = new StringBuilder();
+    String deadlineName = isAbeforeB(contextDeadline, deadline) ? "Context" : "CallOptions";
     if (remainingNanos < 0) {
-      buf.append("ClientCall started after deadline exceeded. Deadline exceeded after -");
+      buf.append("ClientCall started after ");
+      buf.append(deadlineName);
+      buf.append(" deadline was exceeded. Deadline has been exceeded for ");
     } else {
-      buf.append("Deadline exceeded after ");
+      buf.append("Deadline ");
+      buf.append(deadlineName);
+      buf.append(" will be exceeded in ");
     }
     buf.append(seconds);
     buf.append(String.format(Locale.US, ".%09d", nanos));

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

@@ -786,7 +786,7 @@ public class ClientCallImplTest {
     verify(callListener, timeout(1000)).onClose(statusCaptor.capture(), any(Metadata.class));
     assertEquals(Status.Code.DEADLINE_EXCEEDED, statusCaptor.getValue().getCode());
     assertThat(statusCaptor.getValue().getDescription())
-        .startsWith("ClientCall started after deadline exceeded");
+        .startsWith("ClientCall started after CallOptions deadline was exceeded");
     verifyNoInteractions(clientStreamProvider);
   }
 

interop-testing/src/main/java/io/grpc/testing/integration/AbstractInteropTest.java

@@ -1241,7 +1241,7 @@ public abstract class AbstractInteropTest {
     } catch (StatusRuntimeException ex) {
       assertEquals(Status.Code.DEADLINE_EXCEEDED, ex.getStatus().getCode());
       assertThat(ex.getStatus().getDescription())
-        .startsWith("ClientCall started after deadline exceeded");
+        .startsWith("ClientCall started after CallOptions deadline was exceeded");
     }
 
     // CensusStreamTracerModule record final status in the interceptor, thus is guaranteed to be
@@ -1274,7 +1274,7 @@ public abstract class AbstractInteropTest {
     } catch (StatusRuntimeException ex) {
       assertEquals(Status.Code.DEADLINE_EXCEEDED, ex.getStatus().getCode());
       assertThat(ex.getStatus().getDescription())
-        .startsWith("ClientCall started after deadline exceeded");
+        .startsWith("ClientCall started after CallOptions deadline was exceeded");
     }
     if (metricsExpected()) {
       MetricsRecord clientStartRecord = clientStatsRecorder.pollRecord(5, TimeUnit.SECONDS);

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

@@ -1736,7 +1736,7 @@ public class XdsNameResolverTest {
     assertThat(testCall).isNull();
     verifyRpcDelayedThenAborted(observer, 4000L, Status.DEADLINE_EXCEEDED.withDescription(
         "Deadline exceeded after up to 5000 ns of fault-injected delay:"
-            + " Deadline exceeded after 0.000004000s. "));
+            + " Deadline CallOptions will be exceeded in 0.000004000s. "));
   }
 
   @Test