mod_proxy_http2: gRPC bi-directional messages stuck

[tschmittni]

Hi,

maybe you can help me out, I am using gRPC bi-directional messaging with grpc-dotnet. When I directly connect client and server, the messages from the client are streamed to the server without any problems. Once I change the client configuration to connect over the mod_proxy_http2 port, the messages are stuck. It seems like they are buffered because once I start sending messages from the server to the client, sometimes the client messages are delivered, too (depending on the timing) and when I shut down the gRPC server, messages also get delivered sometimes.

Here is my apache configuration:

Protocols h2
SSLProxyEngine On

<Location /tunnel.TunnelMessaging>
    Require all granted
    
    ProxyPass h2://localhost:5001/tunnel.TunnelMessaging retry=0
    ProxyPassReverse https://localhost:5001/tunnel.TunnelMessaging
</Location>

And the debug log output:

• Sending the message which is not received: apache.log
• Logs when shutting down gRPC server: shutting_down_grpc_server.log

Any help would be appreciated!

[icing]

What versions of apache and mod_proxy_http2 are you running?

[tschmittni]

Apache 2.4.46

[icing]

The logs looks as if the client sends a POST with 27 bytes of body, but does not set the end-of-stream flag (flags=0):

recv FRAME[DATA[length=27, flags=0, stream=1, padlen=0]], frames=4/3

and sends nothing ever after. This is buffered, it seems, waiting for more data from the client or an EOS indicator.

[tschmittni]

Thank you for looking through my logs! Yeah, that is exactly what I am seeing.

I have to look for the gRPC specification but my guess would be that with bi-directional streaming the EOS is not sent because the client could potentially stream additional payloads. Shouldn't the mod_proxy_http2 eventually flush the buffer and forward it downstream? Is there a way to disable buffering so I can validate that this is the root-cause?

[icing]

No, there is no option to disable this.

I am not very familiar with the gRPC spec, but do they not use a h2 stream for each procedure call? They need to EOS the request stream, but might never have noticed when talking to their own server.

[tschmittni]

For unary-calls I think this is the case. Each procedure call finishes with EOS. But I don't think this is the case for streaming when the client keeps sending messages over the same h2 stream (as far as I know)

looking here:

• https://github.com/grpc/grpc/blob/master/doc/PROTOCOL-HTTP2.md
• https://docs.microsoft.com/en-us/aspnet/core/grpc/performance?view=aspnetcore-3.1

gRPC bidirectional streaming can be used to replace unary gRPC calls in high-performance scenarios. Once a bidirectional stream has started, streaming messages back and forth is faster than sending messages with multiple unary gRPC calls. Streamed messages are sent as data on an existing HTTP/2 request and eliminates the overhead of creating a new HTTP/2 request for each unary call.

[icing]

That is certainly more performant when it works.

/irony off

As you found out, the assumption that gRPC makes here about data handling behaviour is not shared by everyone. I did not find this "long streaming" requests in the original grpc docs. Is this an invention by Microsoft? Looks like it.

[tschmittni]

I just validated that this is not Microsoft-specific. I have just picked a random bi-directional streaming example which is written in golang (also to make sure I didn't do anything wrong in my example):
e.g. https://github.com/pahanini/go-grpc-bidirectional-streaming-example

With exactly the same result. It looks like this is just how gRPC-based streaming works.

Could you give me some pointers at the proxy_http2 code base where I could try out disabling buffering? Or forward the data once I receive a data frame..

[tschmittni]

btw. I think other HTTP2/gRPC proxies actually have custom handling for gRPC streaming, e.g. HAProxy (see https://www.haproxy.com/blog/haproxy-1-9-2-adds-grpc-support/)

When streaming data from the client to the server, be sure not to set option http-buffer-request. This would pause HAProxy until it receives the full request body, which, when streaming, will be a long time in coming.

[icing]

If I make a test implementation of such a feature, can you build from here and verify it?

[tschmittni]

Would be awesome if you were willing to spend the time on this. Sure thing, I am happy to help out. I can build it from here and test against the .net and golang gRPC implementations.

[tschmittni]

Have you had a chance to look into it? If you don't have time, maybe you can give me some directions so that I can try to put up a PR...

[icing]

Thanks for the offer. It has been second on my list of things for the last week. Let me get another look, maybe I find a good approach or can give you some pointers.

[icing]

You can check the current master if this already solves the problem.

[tschmittni]

Just tried it out, no luck so far. Looks like the on_state_event is not even invoked. I have added some logging around on_state_enter and on_state_event and I only see calls to on_state_enter:

on_state_event_not_invoked.txt

[icing]

My bad. Will have another shot at it pbly tomorrow.

[icing]

Could you try the latest master whenever you have the time? Thanks!

[tschmittni]

I have tried it out, but it seems like it doesn't get called there either. See log:
log_output_client_has_sent_message.txt

It looks like it reads blocking from the stream until EOS which does never arrive.

I have also tried to move the flush call in the beginning of the on_event method, there it actually gets called but without any effect:

static int on_event(h2_stream* stream, h2_stream_event_t ev) {
   if (H2_SEV_IN_DATA_PENDING == ev) {
        h2_stream_flush_input(stream);
    }
   if (stream->monitor && stream->monitor->on_event) {
...
}

I have uploaded my C# grpc example which reproduces the problem. The readme explains the apache set up and how to run the example:
https://github.com/tschmittni/grpc-bidirectional-csharp

Maybe this helps you to reproduce and debug the problem.

[icing]

Thanks for testing. Yes, I agree that I need to write a test case for this. Thanks for the input!

[icing]

Next iterations: i wrote a test case for the behaviour as I understand it and fixed the buffering. There is a new directive to switch the output buffering off. Please give this a try.

[tschmittni]

Ok, I configured my apache to disable output buffering with H2OutputBuffering Off
But it seems like the same problem. I added logging to the secondary_out method but it doesn't get called at all (until I actually shutdown the connection but not after sending the message from the client).

Does it just wait for more data from the input/client stream? It outputs the following and then just waits for more data:

[Wed Nov 04 15:38:26.594297 2020] [http2:trace2] [pid 11008:tid 2188] h2_stream.c(504): [client ::1:57825] h2_stream(41-1,OPEN): recv DATA, len=32
[Wed Nov 04 15:38:26.594297 2020] [http2:trace2] [pid 11008:tid 2188] h2_stream.c(343): [client ::1:57825] h2_stream(41-1,OPEN): dispatch event 4
[Wed Nov 04 15:38:26.594297 2020] [http2:trace2] [pid 11008:tid 2188] h2_stream.c(355): [client ::1:57825] h2_stream(41-1,OPEN): non-state event 4
[Wed Nov 04 15:38:26.594297 2020] [http2:debug] [pid 11008:tid 2188] h2_session.c(337): [client ::1:57825] AH03066: h2_session(41,BUSY,1): recv FRAME[DATA[length=32, flags=0, stream=1, padlen=0]], frames=4/3 (r/s)
[Wed Nov 04 15:38:26.594297 2020] [http2:debug] [pid 11008:tid 2188] h2_session.c(359): [client ::1:57825] AH02923: h2_stream(41-1,OPEN): DATA, len=32, flags=0
[Wed Nov 04 15:38:26.594297 2020] [http2:trace2] [pid 11008:tid 2188] h2_filter.c(63): [client ::1:57825] h2_session(41,BUSY,1): fed 41 bytes to nghttp2, 41 read
[Wed Nov 04 15:38:26.594297 2020] [http2:trace1] [pid 11008:tid 2188] h2_filter.c(143): [client ::1:57825] h2_session(41): read, NONBLOCK_READ, mode=0, readbytes=65536

once I actually shut down the connection, the stream wakes up and flushes the following output:

[Wed Nov 04 15:39:46.641445 2020] [http2:trace1] [pid 11008:tid 2188] h2_session.c(1694): [client ::1:57825] AH03078: h2_session(41,BUSY,1): transit [WAIT] -- stream change --> [BUSY]
[Wed Nov 04 15:39:46.641445 2020] [http2:trace1] [pid 11008:tid 2188] h2_filter.c(143): [client ::1:57825] h2_session(41): read, NONBLOCK_READ, mode=0, readbytes=65536
[Wed Nov 04 15:39:46.641445 2020] [http2:trace1] [pid 11008:tid 2188] h2_filter.c(190): (11)Resource temporarily unavailable: [client ::1:57825] h2_session(41): read
[Wed Nov 04 15:39:46.641445 2020] [http2:trace2] [pid 11008:tid 2188] h2_mplx.c(1109): [client ::1:57825] h2_mplx(41): dispatch events
[Wed Nov 04 15:39:46.641445 2020] [http2:trace2] [pid 11008:tid 2188] h2_session.c(1511): [client ::1:57825] h2_stream(41-1,OPEN): on_resume
[Wed Nov 04 15:39:46.641445 2020] [http2:trace2] [pid 11008:tid 2188] h2_stream.c(180): [client ::1:57825] h2_stream(41-1,OPEN): out-buffer(add_buffered_data())
[Wed Nov 04 15:39:46.641445 2020] [http2:trace2] [pid 11008:tid 2188] h2_stream.c(180): [client ::1:57825] h2_stream(41-1,OPEN): out-buffer(pre())
[Wed Nov 04 15:39:46.641445 2020] [http2:trace2] [pid 11008:tid 2188] h2_stream.c(180): [client ::1:57825] h2_stream(41-1,OPEN): out-buffer(post(H2HEADERS BEAM[38] FLUSH))
[Wed Nov 04 15:39:46.641445 2020] [http2:trace2] [pid 11008:tid 2188] h2_stream.c(180): [client ::1:57825] h2_stream(41-1,OPEN): out-buffer(add_buffered_data(H2HEADERS BEAM[38] FLUSH))

[icing]

First of all, thanks for your patience in working this out.

I added a test case for a mod_proxy_http2 setup and this also works for me. To eliminate that the new buffering flag somehow is not in effect for you, I added a TRACE2 statement that gives the flag value on output.

Please let me know what you see on your system. Thanks!

[tschmittni]

No worries, thanks you a lot for your quick feedback!

I've added already the exact same log entry and I even put a log entry in the beginning of the secondary_out function. And it looks like the function is not called at all. (just when I close the connection, that's how I know the logging was working, and once I close the connection the data flushed either way, whether the buffering flag is on or off).

I also debugged a bit and if I understand the code right, the buffering is already happening earlier while reading from the input stream and the stream just goes to sleep waiting for more data.

[icing]

I have a test case 712_02 added that h2 proxies against itself. I send a h2 request and chunk several input pieces, each 300ms apart and watch when the output arrives. This works fine. I seem to be missing something in our traffic flow that is different.

For you to compare I sent you the log of the test case. Maybe you can spot what is going on here...
test_712_02-error.log

[icing]

Unable to reproduce.

[a4chet]

Tried this in 2.4.52 on Windows and it does work with unary & server side streaming, partial config below...

# Main host
<VirtualHost _default_:443>
    ServerAdmin webmaster@dummy-host.example.com
    DocumentRoot "C:/Apache24/htdocs"
    ServerName localhost
    ServerAlias apache-httpd
    	
    Protocols h2 http/1.1

    SSLEngine on    
    SSLCertificateFile "C:/Apache24/certs/..."
    SSLCertificateKeyFile "C:/Apache24/certs/..."
    LogLevel proxy:info
    
    ############### GRPC Proxying #####################
    SSLProxyEngine on
    SSLProxyMachineCertificateFile "C:/Apache24/certs/..."
    SSLProxyVerify none
    SSLProxyCheckPeerCN off
    SSLProxyCheckPeerName off
    SSLProxyCheckPeerExpire off
    H2OutputBuffering off
    Timeout 600

    <Location "/svc">
      LogLevel http2:info
      LogLevel proxy_http2:info
      
      ProxyPass h2://<backend>
      ProxyPassReverse https://<backend>
    </Location>
    ############### END GRPC Proxying #####################
    ...