gRPC: Random CANCELLED exception on RPC calls

Question

I'm occasionally getting cancellation errors when calling gRPC methods.

Here's my client-side code (Using grpc-java 1.22.0 library):

public class MyClient {
    private static final Logger logger = LoggerFactory.getLogger(MyClient.class);
    private ManagedChannel channel; 
    private FooGrpc.FooStub fooStub;

    private final StreamObserver<Empty> responseObserver = new StreamObserver<>() {
        @Override
        public void onNext(Empty value) {
        }

        @Override
        public void onError(Throwable t) {
            logger.error("Error: ", t);
        }

        @Override
        public void onCompleted() {
        }
    };

    public MyClient() {
        this.channel = NettyChannelBuilder
            .forAddress(host, port)
            .sslContext(GrpcSslContexts.forClient().trustManager(certStream).build())
            .build();
        var pool = Executors.newCachedThreadPool(
                new ThreadFactoryBuilder().setNameFormat("foo-pool-%d").build());
        this.fooStub = FooGrpc.newStub(channel)
                .withExecutor(pool);
    }

    public void callFoo() {
        fooStub.withDeadlineAfter(500L, TimeUnit.MILLISECONDS)
                .myMethod(whatever, responseObserver);
    }
}

When I invoke callFoo() method, it usually works. Client sends a message and server receives it without problem.

But this call occasionally gives me an error:

io.grpc.StatusRuntimeException: CANCELLED: io.grpc.Context was cancelled without error
        at io.grpc.Status.asRuntimeException(Status.java:533) ~[handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:442) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:700) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:399) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:507) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:66) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:627) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:515) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:686) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:675) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) [handler-0.0.1-SNAPSHOT.jar:?]
        at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) [handler-0.0.1-SNAPSHOT.jar:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]

The weird thing is that even though the call gives an error at client side, the server does receive the request, mostly. But sometimes the server misses it.

It is not even DEADLINE_EXCEEDED exception, it just throws CANCELLED: io.grpc.Context was cancelled without error. No other description is provided, So I cannot figure out why this is happening.

To summarize:

1. gRPC call from client randomly gives CANCELLED error.
2. When the error happens, the server sometimes gets the call, but sometimes not.

Answer 1

grpc-java supports automatic deadline and cancellation propagation. When an inbound RPC causes outbound RPCs, those outbound RPCs inherit the inbound RPC's deadline. Also, if the inbound RPC is cancelled the outbound RPCs will be cancelled.

This is implemented via io.grpc.Context. If you do an outbound RPC that you want to live longer than the inbound RPC, you should use Context.fork().

public void myRpcMethod(Request req, StreamObserver<Response> observer) {
  // ctx has all the values as the current context, but
  // won't be cancelled
  Context ctx = Context.current().fork();
  // Set ctx as the current context within the Runnable
  ctx.run(() -> {
    // Can start asynchronous work here that will not
    // be cancelled when myRpcMethod returns
  });
  observer.onNext(generateReply());
  observer.onCompleted();
}