diff --git a/core/src/main/java/io/grpc/internal/ClientCallImpl.java b/core/src/main/java/io/grpc/internal/ClientCallImpl.java index 31286c2bd7..000ede7705 100644 --- a/core/src/main/java/io/grpc/internal/ClientCallImpl.java +++ b/core/src/main/java/io/grpc/internal/ClientCallImpl.java @@ -72,6 +72,7 @@ final class ClientCallImpl extends ClientCall { 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 method; private final Tag tag; @@ -259,10 +260,12 @@ final class ClientCallImpl extends ClientCall { } else { ClientStreamTracer[] tracers = GrpcUtil.getClientStreamTracers(callOptions, headers, 0, false); - stream = new FailingClientStream( - DEADLINE_EXCEEDED.withDescription( - "ClientCall started after deadline exceeded: " + effectiveDeadline), - tracers); + String deadlineName = + isFirstMin(callOptions.getDeadline(), context.getDeadline()) ? "CallOptions" : "Context"; + String description = String.format( + "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 extends ClientCall { 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); diff --git a/core/src/main/java/io/grpc/internal/DelayedClientCall.java b/core/src/main/java/io/grpc/internal/DelayedClientCall.java index 42cedddd0e..ee600e52d6 100644 --- a/core/src/main/java/io/grpc/internal/DelayedClientCall.java +++ b/core/src/main/java/io/grpc/internal/DelayedClientCall.java @@ -81,6 +81,17 @@ public class DelayedClientCall extends ClientCall { 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 extends ClientCall { } 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 extends ClientCall { 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)); diff --git a/core/src/test/java/io/grpc/internal/ClientCallImplTest.java b/core/src/test/java/io/grpc/internal/ClientCallImplTest.java index e409f2f9df..687a89abdd 100644 --- a/core/src/test/java/io/grpc/internal/ClientCallImplTest.java +++ b/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); } diff --git a/interop-testing/src/main/java/io/grpc/testing/integration/AbstractInteropTest.java b/interop-testing/src/main/java/io/grpc/testing/integration/AbstractInteropTest.java index bd11bac8a9..d04873c5a9 100644 --- a/interop-testing/src/main/java/io/grpc/testing/integration/AbstractInteropTest.java +++ b/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); diff --git a/xds/src/test/java/io/grpc/xds/XdsNameResolverTest.java b/xds/src/test/java/io/grpc/xds/XdsNameResolverTest.java index 2deab4ae68..f4475ebe37 100644 --- a/xds/src/test/java/io/grpc/xds/XdsNameResolverTest.java +++ b/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