From 25d414b2a875c9020796da35c8e1f2393bbbb466 Mon Sep 17 00:00:00 2001 From: Eric Anderson Date: Mon, 29 Jun 2026 12:57:48 -0700 Subject: [PATCH 1/2] 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. --- .../io/grpc/internal/DelayedClientCall.java | 12 +++++- .../io/grpc/internal/ManagedChannelImpl.java | 9 +++-- .../grpc/internal/DelayedClientCallTest.java | 39 +++++++++++-------- .../main/java/io/grpc/xds/FaultFilter.java | 2 +- .../java/io/grpc/xds/XdsNameResolverTest.java | 2 +- 5 files changed, 40 insertions(+), 24 deletions(-) diff --git a/core/src/main/java/io/grpc/internal/DelayedClientCall.java b/core/src/main/java/io/grpc/internal/DelayedClientCall.java index e0c05ca637e..db057e7728e 100644 --- a/core/src/main/java/io/grpc/internal/DelayedClientCall.java +++ b/core/src/main/java/io/grpc/internal/DelayedClientCall.java @@ -49,6 +49,9 @@ */ public class DelayedClientCall extends ClientCall { 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 extends ClientCall { private DelayedListener 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 diff --git a/core/src/main/java/io/grpc/internal/ManagedChannelImpl.java b/core/src/main/java/io/grpc/internal/ManagedChannelImpl.java index e423220e3ad..1c23b1fa69d 100644 --- a/core/src/main/java/io/grpc/internal/ManagedChannelImpl.java +++ b/core/src/main/java/io/grpc/internal/ManagedChannelImpl.java @@ -986,9 +986,12 @@ private final class PendingCall extends DelayedClientCall method, CallOptions callOptions) { - super(getCallExecutor(callOptions), scheduledExecutor, callOptions.getDeadline()); + PendingCall(Context context, MethodDescriptor method, CallOptions callOptions) { + super( + "name_resolver", + getCallExecutor(callOptions), + scheduledExecutor, + callOptions.getDeadline()); this.context = context; this.method = method; this.callOptions = callOptions; diff --git a/core/src/test/java/io/grpc/internal/DelayedClientCallTest.java b/core/src/test/java/io/grpc/internal/DelayedClientCallTest.java index 0d30e947b0c..cd7d71daab4 100644 --- a/core/src/test/java/io/grpc/internal/DelayedClientCallTest.java +++ b/core/src/test/java/io/grpc/internal/DelayedClientCallTest.java @@ -66,8 +66,8 @@ public class DelayedClientCallTest { @Test public void allMethodsForwarded() throws Exception { - DelayedClientCall delayedClientCall = - new DelayedClientCall<>(callExecutor, fakeClock.getScheduledExecutorService(), null); + DelayedClientCall 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 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 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 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 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 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 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 delayedClientCall = Context.current().withValue(contextKey, goldenValue).call(() -> - new DelayedClientCall<>(callExecutor, fakeClock.getScheduledExecutorService(), null)); + new DelayedClientCall<>( + "test", callExecutor, fakeClock.getScheduledExecutorService(), null)); AtomicReference readyContext = new AtomicReference<>(); delayedClientCall.start(new ClientCall.Listener() { @Override public void onReady() { @@ -232,7 +237,7 @@ public void delayedCallsRunUnderContext() throws Exception { @Test public void listenerThrowsInPendingCallback_cancelsRealCall() { DelayedClientCall delayedClientCall = new DelayedClientCall<>( - callExecutor, fakeClock.getScheduledExecutorService(), null); + "test", callExecutor, fakeClock.getScheduledExecutorService(), null); final RuntimeException boom = new RuntimeException("boom"); ClientCall.Listener throwingListener = new ClientCall.Listener() { @Override @@ -261,7 +266,7 @@ public void start(Listener listener, Metadata metadata) { @Test public void listenerThrowsInPendingOnHeaders_cancelsRealCall() { DelayedClientCall delayedClientCall = new DelayedClientCall<>( - callExecutor, fakeClock.getScheduledExecutorService(), null); + "test", callExecutor, fakeClock.getScheduledExecutorService(), null); final RuntimeException boom = new RuntimeException("boom"); ClientCall.Listener throwingListener = new ClientCall.Listener() { @Override @@ -286,7 +291,7 @@ public void start(Listener listener, Metadata metadata) { @Test public void listenerThrowsInPendingOnReady_cancelsRealCall() { DelayedClientCall delayedClientCall = new DelayedClientCall<>( - callExecutor, fakeClock.getScheduledExecutorService(), null); + "test", callExecutor, fakeClock.getScheduledExecutorService(), null); final RuntimeException boom = new RuntimeException("boom"); ClientCall.Listener throwingListener = new ClientCall.Listener() { @Override @@ -311,7 +316,7 @@ public void start(Listener listener, Metadata metadata) { @Test public void onCloseExceptionCaughtAndLogged() { DelayedClientCall delayedClientCall = new DelayedClientCall<>( - callExecutor, fakeClock.getScheduledExecutorService(), null); + "test", callExecutor, fakeClock.getScheduledExecutorService(), null); final RuntimeException boom = new RuntimeException("boom"); final AtomicReference observed = new AtomicReference<>(); ClientCall.Listener throwingListener = new ClientCall.Listener() { @@ -339,7 +344,7 @@ public void start(Listener listener, Metadata metadata) { @Test public void listenerThrowsInPassThroughOnMessage_cancelsRealCall() { DelayedClientCall delayedClientCall = new DelayedClientCall<>( - callExecutor, fakeClock.getScheduledExecutorService(), null); + "test", callExecutor, fakeClock.getScheduledExecutorService(), null); final RuntimeException boom = new RuntimeException("boom"); ClientCall.Listener throwingListener = new ClientCall.Listener() { @Override @@ -362,7 +367,7 @@ public void onMessage(Integer msg) { @Test public void listenerThrowsInPassThroughOnHeaders_cancelsRealCall() { DelayedClientCall delayedClientCall = new DelayedClientCall<>( - callExecutor, fakeClock.getScheduledExecutorService(), null); + "test", callExecutor, fakeClock.getScheduledExecutorService(), null); final RuntimeException boom = new RuntimeException("boom"); ClientCall.Listener throwingListener = new ClientCall.Listener() { @Override @@ -385,7 +390,7 @@ public void onHeaders(Metadata headers) { @Test public void listenerThrowsInPassThroughOnReady_cancelsRealCall() { DelayedClientCall delayedClientCall = new DelayedClientCall<>( - callExecutor, fakeClock.getScheduledExecutorService(), null); + "test", callExecutor, fakeClock.getScheduledExecutorService(), null); final RuntimeException boom = new RuntimeException("boom"); ClientCall.Listener throwingListener = new ClientCall.Listener() { @Override @@ -408,7 +413,7 @@ public void onReady() { @Test public void listenerThrowsInPassThrough_subsequentCallbacksSwallowedAndOnCloseOverridden() { DelayedClientCall delayedClientCall = new DelayedClientCall<>( - callExecutor, fakeClock.getScheduledExecutorService(), null); + "test", callExecutor, fakeClock.getScheduledExecutorService(), null); final RuntimeException boom = new RuntimeException("boom"); final AtomicReference lastMessage = new AtomicReference<>(); final AtomicReference closeStatus = new AtomicReference<>(); diff --git a/xds/src/main/java/io/grpc/xds/FaultFilter.java b/xds/src/main/java/io/grpc/xds/FaultFilter.java index db37490d7c2..4aded91547f 100644 --- a/xds/src/main/java/io/grpc/xds/FaultFilter.java +++ b/xds/src/main/java/io/grpc/xds/FaultFilter.java @@ -414,7 +414,7 @@ private final class DelayInjectedCall extends DelayedClientCall> callSupplier) { - super(callExecutor, scheduler, deadline); + super("httpfault_filter", callExecutor, scheduler, deadline); activeFaultCounter.incrementAndGet(); ScheduledFuture task = scheduler.schedule( new Runnable() { diff --git a/xds/src/test/java/io/grpc/xds/XdsNameResolverTest.java b/xds/src/test/java/io/grpc/xds/XdsNameResolverTest.java index 3d8d96a89f5..044e1715def 100644 --- a/xds/src/test/java/io/grpc/xds/XdsNameResolverTest.java +++ b/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 From d8529629c7ceb4d89d52afe1db975ca72a7b1115 Mon Sep 17 00:00:00 2001 From: Eric Anderson Date: Tue, 30 Jun 2026 08:52:09 -0700 Subject: [PATCH 2/2] Fix ext_proc --- .../java/io/grpc/xds/ExternalProcessorClientInterceptor.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/xds/src/main/java/io/grpc/xds/ExternalProcessorClientInterceptor.java b/xds/src/main/java/io/grpc/xds/ExternalProcessorClientInterceptor.java index 04a4e749dca..971b3c21afb 100644 --- a/xds/src/main/java/io/grpc/xds/ExternalProcessorClientInterceptor.java +++ b/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 extends DelayedClientCall { DataPlaneDelayedCall( Executor executor, ScheduledExecutorService scheduler, @Nullable Deadline deadline) { - super(executor, scheduler, deadline); + super("ext_proc", executor, scheduler, deadline); } }