Grpc-java: io.grpc.StatusRuntimeException when using shutdownNow

[Randgalt]

What version of gRPC-Java are you using?

1.26.0

What is your environment?

Mac Java 8/11

What did you expect to see?

No exception

What did you see instead?

io.grpc.StatusRuntimeException: UNAVAILABLE: Channel shutdownNow invoked
    at io.grpc.Status.asRuntimeException(Status.java:533)
    at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:449)
    at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
    at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
    at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
    at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:700)
    at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
    at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
    at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
    at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:399)
    at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:521)
    at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:66)
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:641)
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:529)
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:703)
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:692)
    at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
    at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

Steps to reproduce the bug

Note this is a BiDi stream call. The client is closing the connection on the server without the server knowing this will happen. This is done by calling:

streamObserver.onCompleted();
channel.shutdownNow();
channel.awaitTermination(maxWaitMs, TimeUnit.MILLISECONDS);

Everything seems to work properly but I see the above exception in my logs. Note: I don't believe this is the same as #4102 as I'm calling shutdownNow() only once.

As an aside, I'd prefer to just call shutdown() instead of shutdownNow() but awaitTermination takes a very long time (10-20 seconds) if I do this. I don't know if it's related.

[creamsoup]

i believe this is intended behavior. it is also stated in the shutdownNow javadoc; Initiates a forceful shutdown in which preexisting and new calls are cancelled. shutdown waits all the existing streams to be finished while it prevents new streams. What you need to do is gracefully close existing streams when you need to shutdown (should be after calling shutdown to prevent new streams).

[Randgalt]

shutdown() is taking a very long time to complete. Is there a good way to debug why? I was calling shutdown() initially but then channel.awaitTermination() takes 10-20 seconds.

[creamsoup]

shutdown is waiting for existing open streams to be finished while it preventing the new streams to be created. if the existing streams are not closed, it will wait until the termination time. can you double check all the streams are closed?

[Randgalt]

Yes - I've doubled checked. There is only stream (BiDi) anyway.

[creamsoup]

BiDi stream also need to be finished. I can't tell the streamObserver.onCompleted(); is for the bidi stream or not. if there isn't any outstanding streams, this is a bug.
can you add a CountDownLatch or log statement to StreamObserver to make sure it was the only stream and closed before the awaitTermination is expired? i checked code and can't find any obvious issue. if it still looks like a bug, can you provide us minimal reproduce? so, we can debug and fix the issue?

[Randgalt]

Here's a test case. Am I doing something wrong or is there a real bug here? https://github.com/Randgalt/grpc-issue-6642

[Randgalt]

FYI - if I change the example to call onCompleted on the server's stream then the test works. I believe this is a bug. Close of a client should not be cooperative. We should be able to gracefully close a client without relying on the server to take action.

[andrm]

I'm not a grpc developer, but I think this is intented.

On bidi streams both sides need to close explicitly. There is no built-in part in the protocol that says that if one side closes its stream the other side needs to close the stream also. You can of course do that in your implementation, as you did in TestServer StreamObserver onCompleted().

You could also send a special message which signals the server that the client is finished. In other contexts this is often called "Packet of Death" or "Kiss of Death message". NTP has this.

In your reproducer client you call newStreamObserver.onCompleted(). That's wrong, since it is a callback when the server calls onCompleted on his side of the stream. The callback should never be called by your code directly.

[Randgalt]

The issue here is the client wants to close and doesn't care if the server knows. We just want to finish any outgoing requests and then shutdown the channel. Of course, we could keep our own count, etc. but it seems like the gRPC channel internally already knows this. If it's not support behavior I guess that's that, but some kind of medium between shutdownNow (i.e. disruptive) and shutdown (has to wait on server) would be useful.

[andrm]

I understand, but in that case you never have the assurance that your outgoing requests have ever reached the server. Usually this is what users want. shutdownNow() is for the "I don't care" case.

(Deleted mention of deadlines)
A good thing is to use the keepalive mechanism to detect that the other side is gone.

[creamsoup]

oops, yes @andrm is right. thanks!
when the client calls onComplete(), it is in http2 half closed state. but the stream is not fully closed. This is because closed on client side doesn't mean the stream is finished since the server may send more data. the stream can be closed if both ends calls onCompleted. Unary rpcs we know we expect to send and receive 1 message to/from server, so it doesn't have this behavior.

[voidzcy]

On bidi streams both sides need to close explicitly. There is no built-in part in the protocol that says that if one side closes its stream the other side needs to close the stream also. You can of course do that in your implementation, as you did in TestServer StreamObserver#onCompleted().

This is exactly what bidi streaming mean. In bidi streaming, client and server streams operate separately. Terminating client's outbound only indicates client will no longer send message to server, but client is still able to receive messages from server. Client tells the server "I am done" but nothing else. In your case, you probably want server to behave "I am also done". You should do this in TestServer StreamObserver#onCompleted().

The issue here is the client wants to close and doesn't care if the server knows.

If this is your intention, people achieve this by calling process.onError(Status.CANCELLED.withDescription("shutdown").asException()) instead of process.onComplete(). (I am not a fan of this...)

[Randgalt]

It seems like there should be some middle ground. Using raw TCP/IP, I send bytes, flush them then close the socket. The server sees the socket close. Of course, I can send a message "clientIsClosingMessage". I'm looking for something similar, flush any pending "onNext" messages then gracefully close the client without waiting on the server.

[creamsoup]

the closing socket part is the problem. it is not graceful, and we might as well call shutdownNow which is slightly more graceful.

I think the "ideal way" to handle graceful shutdown (or closing bidi stream in general) is

on the server side, when the "inbound observer" detect the client side's onCompleted(). the server can be in the graceful stream close mode. it can wrap up existing work (including sending messages if necessary), and closed the stream by calling "outbound observer"'s onCompleted(). then both side is closed; the stream is fully closed.

the reason I refer to it as the ideal way is if the server is not handling it correctly, it can leak the stream (e.g. server never call onCompleted). it will still work/behaves fine until the http2 max stream limit reached. that's why calling onError with Status.CANCELLED is sometimes recommended. This way it is more likely finished even if the server implementation is not handling the close correctly.

    @Override
    public StreamObserver<TestRequest> process(StreamObserver<TestResponse> responseObserver) {
        return new StreamObserver<TestRequest>() {
            @Override
            public void onNext(TestRequest value) {
                // ...
            }

            @Override
            public void onError(Throwable t) {
                // ...
            }

            @Override
            public void onCompleted() {
                doWrapUp();
                responseObserver.onCompleted();
            }
        };
    }

[creamsoup]

@Randgalt, sorry to make you write the repro. i think my previous comment should answer your question. if you have any more questions feel free to reopen.