How can the server detect/display when the client sends a message that is too big

[Rocha Stratovan]

I am using gRPC versions:

• gRPC-protoc:26.1
• gRPC-lib:1.63.0

How can my C++ server code detect when the client has sent a message that is larger than the server's maximum size (currently using the 4 MB default).

I know how to restart my server with a larger size to get this to work. However, I want to be able to provide meaningful log information when this happens.

The current client / server environment is one where any time there is a problem "it's the servers fault", and "it's a hassle to reproduce the problem with debug flags enabled."

This is an example of the service my server is implementing.

```
  rpc upload (stream StreamElement) returns (google.protobuf.Empty ) {}
```

And the basic skeleton of how the server works

```
grpc::Status
MyStream::upload(
        grpc::ServerContext*                         context,
        grpc::ServerReader<gRPCDicosStreamElement>*  reader,
        ::google::protobuf::Empty*                   response)
{
    StreamElement  element;


    while(reader->Read(&element))
    {
        ... do stuff to receive the element
    }


    // Detect abnormal stream termination
    if (context->IsCancelled())
    {
        ... do canceled stuff, logging, etc....
        return grpc::Status(grpc::StatusCode::CANCELLED, "Client cancelled");
    }

    return grpc::Status::OK;
}
```


I'm looking at DETECTING when a gRPC session is stopped/canceled/killed/errored
because of a message size issue. I need to detect that this problem happened so
my software can clearly instruct the user to restart the server with a larger
size.

The problem was originally observed as the following

1. Client sends a streaming message to me, the server.
2. Client sends a message that is larger than the 4 MB default.
3. The client is ignoring the return status, and claims the server is broken.
4. After a long debugging session I learned about the client / server message size conflict.

On the server

• I found that `read()` will return false because the stream has ended
• and surprisingly `context->IsCancelled()` will also return false.

So my server code thinks all is good, tries to process the accumulated stream of data and fails.

It appears the gRPC layer is detecting the problem, shutting things down and not informing me, the server application.

I tried using Message Interceptors to look into this further.


Message Intercept Test #1 - PRE_SEND_STATUS

First I used the hook for PRE_SEND_STATUS to view the status, but I found this was the status set/returned by my `upload()` logic.


Message Intercept Test #2 - EVERYTHING

This is where things get interesting.

I thought I would go big and so I created an interceptor that would print the current callback hook every time it's invoked.


If I use my library's logging method I see:

1. POST_RECV_INITIAL_METADATA
2. followed by a ton of POST_RECV_MESSAGE
3. And then logs from my code that triggers when the upload() logic has completed. Part of which is an error about bad data received.

However, if I use std::cerr and std::endl instead of my library's logging I see:

1. POST_RECV_INITIAL_METADATA
2. followed by a ton of POST_RECV_MESSAGE
3. Now, is_canceled() returns true and I get the expected desired failure

Does anyone know how to do this correctly? I find it hard to believe that the library layer doesn't propagate a failure condition like this up to the application. I feel like I'm missing an API or method or pattern that would help me with this.

Thank you,

John

[Rocha Stratovan]

I forgot to add.

This is the log information I observed when I turned on 

GRPC_VERBOSITY=DEBUG GRPC_TRACE=transport,http

I0513 16:05:24.558000000 50932 chttp2_transport.cc:2981] ipv4:192.168.100.153:54010: Keepalive ping cancelled. Resetting timer.
I0513 16:05:24.558000000 50932 chttp2_transport.cc:2814] ipv4:192.168.100.153:54010: Complete BDP ping err=OK
I0513 16:05:24.603000000 62328 chttp2_transport.cc:1623] perform_stream_op[s=000001F8A1A2EE50; op=000001F89F5DC9F8]:  CANCEL:RESOURCE_EXHAUSTED:SERVER: Received message larger than max (382267226 vs. 4194304) {grpc_status:8}
I0513 16:05:24.603000000 62328 chttp2_transport.cc:1623] perform_stream_op[s=000001F8A1A2EE50; op=000001F89F5DD5F8]:  CANCEL:RESOURCE_EXHAUSTED:SERVER: Received message larger than max (382267226 vs. 4194304) {grpc_status:8}
I0513 16:05:24.603000000 62328 chttp2_transport.cc:1623] perform_stream_op[s=000001F8A1A2EE50; op=000001F89F5DBAF8]:  CANCEL:RESOURCE_EXHAUSTED:SERVER: Received message larger than max (382267226 vs. 4194304) {grpc_status:8}
I0513 16:05:24.603000000 62328 chttp2_transport.cc:1623] perform_stream_op[s=000001F8A1A2EE50; op=000001F89F5DCCF8]:  CANCEL:CANCELLED
I0513 16:05:24.603000000 62328 chttp2_transport.cc:1623] perform_stream_op[s=000001F8A1A2EE50; op=000001F89F5DBEF8]:  CANCEL:CANCELLED
I0513 16:05:24.603000000 62328 chttp2_transport.cc:1623] perform_stream_op[s=000001F8A1A2EE50; op=000001F89F5DC1F8]:  CANCEL:CANCELLED
I0513 16:05:24.603000000 62328 chttp2_transport.cc:1356] perform_stream_op_locked[s=000001F8A1A2EE50; op=000001F89F5DC9F8]:  CANCEL:RESOURCE_EXHAUSTED:SERVER: Received message larger than max (382267226 vs. 4194304) {grpc_status:8}; on_complete = 000001F8A1ADFFC0
D0513 16:05:24.603000000 62328 chttp2_transport.cc:2304] MARK_STREAM_CLOSED: t=000001F8A19EBB20 s=000001F8A1A2EE50(id=3) read+write [RESOURCE_EXHAUSTED:SERVER: Received message larger than max (382267226 vs. 4194304) {grpc_status:8}]
D0513 16:05:24.603000000 62328 chttp2_transport.cc:2092] maybe_complete_recv_trailing_metadata cli=0 s=000001F8A1A2EE50 closure=000001F8A1A2EE18 read_closed=1 write_closed=1 116726
D0513 16:05:24.603000000 62328 chttp2_transport.cc:2092] maybe_complete_recv_trailing_metadata cli=0 s=000001F8A1A2EE50 closure=0000000000000000 read_closed=1 write_closed=1 0
I0513 16:05:24.604000000 62328 chttp2_transport.cc:919] W:000001F8A19EBB20 SERVER [ipv4:192.168.100.153:54010] state IDLE -> WRITING [CLOSE_FROM_API]
I0513 16:05:24.604000000 62328 chttp2_transport.cc:1284] complete_closure_step: t=000001F8A19EBB20 000001F8A1ADFFC0 refs=0 flags=0x0000 desc=op->on_complete err=OK write_state=WRITING whence=(null):-1
I0513 16:05:24.604000000 62328 chttp2_transport.cc:1356] perform_stream_op_locked[s=000001F8A1A2EE50; op=000001F89F5DD5F8]:  CANCEL:RESOURCE_EXHAUSTED:SERVER: Received message larger than max (382267226 vs. 4194304) {grpc_status:8}; on_complete = 000001F8A1ADFF80
D0513 16:05:24.604000000 62328 chttp2_transport.cc:2304] MARK_STREAM_CLOSED: t=000001F8A19EBB20 s=000001F8A1A2EE50(id=3) read+write [RESOURCE_EXHAUSTED:SERVER: Received message larger than max (382267226 vs. 4194304) {grpc_status:8}]
D0513 16:05:24.604000000 62328 chttp2_transport.cc:2092] maybe_complete_recv_trailing_metadata cli=0 s=000001F8A1A2EE50 closure=0000000000000000 read_closed=1 write_closed=1 0
I0513 16:05:24.604000000 62328 chttp2_transport.cc:1284] complete_closure_step: t=000001F8A19EBB20 000001F8A1ADFF80 refs=0 flags=0x0000 desc=op->on_complete err=OK write_state=WRITING whence=(null):-1
I0513 16:05:24.604000000 62328 chttp2_transport.cc:1356] perform_stream_op_locked[s=000001F8A1A2EE50; op=000001F89F5DBAF8]:  CANCEL:RESOURCE_EXHAUSTED:SERVER: Received message larger than max (382267226 vs. 4194304) {grpc_status:8}; on_complete = 000001F8A1ADF9C0
D0513 16:05:24.604000000 62328 chttp2_transport.cc:2304] MARK_STREAM_CLOSED: t=000001F8A19EBB20 s=000001F8A1A2EE50(id=3) read+write [RESOURCE_EXHAUSTED:SERVER: Received message larger than max (382267226 vs. 4194304) {grpc_status:8}]
D0513 16:05:24.604000000 62328 chttp2_transport.cc:2092] maybe_complete_recv_trailing_metadata cli=0 s=000001F8A1A2EE50 closure=0000000000000000 read_closed=1 write_closed=1 0
I0513 16:05:24.604000000 62328 chttp2_transport.cc:1284] complete_closure_step: t=000001F8A19EBB20 000001F8A1ADF9C0 refs=0 flags=0x0000 desc=op->on_complete err=OK write_state=WRITING whence=(null):-1
I0513 16:05:24.604000000 62328 chttp2_transport.cc:1356] perform_stream_op_locked[s=000001F8A1A2EE50; op=000001F89F5DCCF8]:  CANCEL:CANCELLED; on_complete = 000001F8A1ADF300
D0513 16:05:24.604000000 62328 chttp2_transport.cc:2304] MARK_STREAM_CLOSED: t=000001F8A19EBB20 s=000001F8A1A2EE50(id=3) read+write [CANCELLED]
D0513 16:05:24.605000000 62328 chttp2_transport.cc:2092] maybe_complete_recv_trailing_metadata cli=0 s=000001F8A1A2EE50 closure=0000000000000000 read_closed=1 write_closed=1 0
I0513 16:05:24.605000000 62328 chttp2_transport.cc:1284] complete_closure_step: t=000001F8A19EBB20 000001F8A1ADF300 refs=0 flags=0x0000 desc=op->on_complete err=OK write_state=WRITING whence=(null):-1
I0513 16:05:24.605000000 62328 chttp2_transport.cc:1356] perform_stream_op_locked[s=000001F8A1A2EE50; op=000001F89F5DBEF8]:  CANCEL:CANCELLED; on_complete = 000001F8A1A007B0
D0513 16:05:24.605000000 62328 chttp2_transport.cc:2304] MARK_STREAM_CLOSED: t=000001F8A19EBB20 s=000001F8A1A2EE50(id=3) read+write [CANCELLED]
D0513 16:05:24.605000000 62328 chttp2_transport.cc:2092] maybe_complete_recv_trailing_metadata cli=0 s=000001F8A1A2EE50 closure=0000000000000000 read_closed=1 write_closed=1 0
I0513 16:05:24.605000000 62328 chttp2_transport.cc:1284] complete_closure_step: t=000001F8A19EBB20 000001F8A1A007B0 refs=0 flags=0x0000 desc=op->on_complete err=OK write_state=WRITING whence=(null):-1
I0513 16:05:24.605000000 62328 chttp2_transport.cc:1356] perform_stream_op_locked[s=000001F8A1A2EE50; op=000001F89F5DC1F8]:  CANCEL:CANCELLED; on_complete = 000001F8A1A016B0
D0513 16:05:24.605000000 62328 chttp2_transport.cc:2304] MARK_STREAM_CLOSED: t=000001F8A19EBB20 s=000001F8A1A2EE50(id=3) read+write [CANCELLED]
D0513 16:05:24.605000000 62328 chttp2_transport.cc:2092] maybe_complete_recv_trailing_metadata cli=0 s=000001F8A1A2EE50 closure=0000000000000000 read_closed=1 write_closed=1 0
I0513 16:05:24.605000000 62328 chttp2_transport.cc:1284] complete_closure_step: t=000001F8A19EBB20 000001F8A1A016B0 refs=0 flags=0x0000 desc=op->on_complete err=OK write_state=WRITING whence=(null):-1
I0513 16:05:24.605000000 62328 chttp2_transport.cc:919] W:000001F8A19EBB20 SERVER [ipv4:192.168.100.153:54010] state WRITING -> WRITING [begin write in current thread]
I0513 16:05:24.606000000 62328 chttp2_transport.cc:919] W:000001F8A19EBB20 SERVER [ipv4:192.168.100.153:54010] state WRITING -> IDLE [finish writing]

[Rocha Stratovan]

Additional information.

The issues continue even after updating to the latest gRPC build:

• gRPC-protoc:31.1;gRPC-lib:1.80.0

Oh, I suppose it may be pertinent that this is occurring on a Windows platform. While we are cross platform I have not checked behavior on Linux.