grpc reports "cancelled before receiving half close" although stream is reset by client

[tryge]

What version of gRPC-Java are you using?

1.26.0

What is your environment?

The problem is 100% reproducible on CentOS and macOS.

What did you expect to see?

On the server side it would be good to see a different reason for the cancelled call in the StatusRuntimeExcpetion e.g. "CANCELLED - client reset stream" or even another Status entirely that makes it easy to differentiate.

Additionally, either no DATA frame should be sent by the client after a RST_STREAM or the NettyServerHandler should ignore it when receiving it directly after the RST_STREAM.

What did you see instead?

A StatusRuntimeException with message CANCELLED: cancelled before receiving half close is delivered to the server's StreamObserver and followed by a:

io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2Exception$StreamException: Received DATA frame for an unknown stream 3
        at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2Exception.streamError(Http2Exception.java:147) ~[grpc-netty-shaded-1.26.0.jar:1.26.0]

Steps to reproduce the bug

Both client and server use grpc-java. We have a bidirectional call, after the stream is established the client's onNext throws an exception. Therefore grpc-java sends a RST_STREAM followed by a DATA frame to the server.

In the server logs this can be observed with:

2019-12-19 15:45:17,819 DEBUG | grpc-default-worker-ELG-3-1 | io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler   | [id: 0x39a99083, L:/<REDACTED>- R:/<REDACTED>] INBOUND RST_STREAM: streamId=3 errorCode=8 
2019-12-19 15:45:17,822 DEBUG | grpc-default-worker-ELG-3-1 | io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler   | [id: 0x39a99083, L:/<REDACTED> - R:/<REDACTED>] INBOUND DATA: streamId=3 padding=0 endStream=true length=0 bytes= 

and then the exception:

io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2Exception$StreamException: Received DATA frame for an unknown stream 3
        at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2Exception.streamError(Http2Exception.java:147) ~[grpc-netty-shaded-1.26.0.jar:1.26.0]
...

What makes the problem hard to diagnose on the server side:

The way the problem presents itself could be a server problem, as you could argue that the server did close the stream and therefore data from the client could be interpreted as a racy frame. This is the reason we spent a few hours debugging it on the server side even though the problem originated on the client side (that my team doesn't have any control over).

Another thing is that we had to deactivate WARN logging on the server side for grpc because these exception traces trashed the log files. Generally we like to observe exceptions logged on WARN because we detected some bugs in our application that way.

[ericgribkoff]

Thanks for opening the issue. To make sure I understand there are two concerns being reported here:

• cancelled before receiving half close is not as informative as another error string, like client reset stream
• After the client resets the stream, Netty gets a data frame on the now-closed stream and generates the StreamException, which gets logged at WARN by gRPC (I believe this happens here

I understand that the message string doesn't correspond neatly to the HTTP/2 level logs, but I think that cancelled before receiving half close might be as informative as it gets at the gRPC protocol level, which is an abstract layer on top of HTTP/2 where the RST_STREAM frame is being processed. (You mention the error code CANCELLED itself, which is mandated by the gRPC spec for this scenario at https://github.com/grpc/grpc/blob/master/doc/PROTOCOL-HTTP2.md#errors)

As for the log spam at WARN, since gRPC is intentionally sending a data frame that will ultimately fail to parse within Netty, it seems fair that we should be able to anticipate this and suppress/lower the severity of the log output in this specific scenario. I'll look into what it would take to get this changed.

[tryge]

Thank you for your answer. I know it seems trivial but it creates work for me because the same message is reported in two completely different situations, one that I have control over which is the server cancelling the request although the client has not closed his end yet, and the other one which I don't have any control over which is the client resetting the stream.

My issue with this is that I'm responsible for this service and it will create a lot of work for me. When our monitoring reports these cancelled before receiving half close errors as alarms, then I need to enable DEBUG logging on a production instance (which I only want to do in exceptional circumstances) to see whether the client has sent a RST_STREAM frame in order to decide whether to tell my team to investigate an issue on our end. (Is there a way to diagnose this without enabling DEBUG logging?)

If the error message were different in both cases we could actually handle the client resetting the stream and I wouldn't have any work with this issue anymore. If you point me in the right direction I'm happy to (try and) fix the issue myself.

A second note, I'm surely not equipped to fully understand the specification you referenced correctly as I haven't read any other part of it, however in my attempt to interpret the following paragraph:

RPC runtime implementations should interpret RST_STREAM as immediate full-closure of the stream and should propagate an error up to the calling application layer.

When it states full-closure it feels the error message reporting a missing half close does not conform to it, although I agree it just says to propagate an error (any error?) to the application level.

[ericgribkoff]

Thanks for providing the additional details as to why this is causing pain, that makes sense.

My issue with this is that I'm responsible for this service and it will create a lot of work for me. When our monitoring reports these cancelled before receiving half close errors as alarms, then I need to enable DEBUG logging on a production instance (which I only want to do in exceptional circumstances) to see whether the client has sent a RST_STREAM frame in order to decide whether to tell my team to investigate an issue on our end. (Is there a way to diagnose this without enabling DEBUG logging?)

There is not another way of diagnosing this as far as I am aware, but cc @ejona86 who may have more ideas here.

[ejona86]

I know it seems trivial but it creates work for me because the same message is reported in two completely different situations, one that I have control over which is the server cancelling the request although the client has not closed his end yet, and the other one which I don't have any control over which is the client resetting the stream.

The throwing of the exception is the annoying one. I hated to add that exception to the stubs, but there was no other way (at the time) to notify the server of cancellation after half close and then there were consistency concerns (if we are going to throw at "random" times, we want you to be reasonably aware we may do that, especially since it is abnormal for the API).

I've not read everything in detail, but I think this may be what you are looking for: if you call serverCallStreamObserver.setOnCancelHandler() (just cast the StreamObserver to ServerCallStreamObserver) before returning your 'inbound' StreamObserver, then grpc will disable throwing an exception when calling onNext(). Is that what you need?

[ejona86]

When it states full-closure it feels the error message reporting a missing half close does not conform to it

Quick note: "half close" isn't the problem, it is just saying when it happened. It is simply a message saying "cancelled" and it provided a bit more context that the cancellation occurred before you received "half close", which means the server hadn't need the client's streamObserver.onComplete() yet.

[tryge]

@ejona86 After peeking into the source code I start to believe that my assumptions are wrong. The API docs for ServerCall.Listener.onCancel() state that cancellation can be caused by timeouts, explicit cancellation by the client, network errors, etc.

Does the server side cancel the call in any circumstances? If not, then everything is fine except for the log spamming on WARN level.

[ejona86]

Right now there is no API for the server to cancel. It can only close. That could change in the future, but doesn't seem likely soon (we discussed it maybe a year ago; main issue is there are up to three different ways to close/cancel and the differences are subtle for most users).

@ericgribkoff, for the log message, it seems we should fix the client so that it doesn't send the useless DATA frame. The log message was useful in that it showed us an implementation was doing something silly, so I'd be inclined to leave it alone.

[ChuckChen123]

I also encountered the same problem, has this problem been solved?

[ChuckChen123]

When will the grpc client send the rst_stream information to the server, I opened the log and found that before the error was reported, the client sent the rst_stream information to the server, but I did not call the onComplete method. Is this the problem?

[ChuckChen123]

When will the grpc client send the rst_stream information to the server, I opened the log and found that before the error was reported, the client sent the rst_stream information to the server, but I did not call the onComplete method. Is this the problem?

I found out what the reason is. I read the file too fast and caused OOM, but the GRPC prompt is CANCELLED: Client sendMessage() failed with Error