grpc client receives "rpc error: code = Internal desc = server closed the stream without sending trailers"

[ajain621]

Hi,

I am introducing a new backend server (a grpc server, say v3 api) alongside our existing backend servers (serving v2 version of our apis). The existing backend servers (python) along with this new server are proxied via apache. Apache is also used to terminate the tls connection. In order to make grpc client work with this grpc server which is proxied via apache, I needed to add the http2 modules to apache. This is done successfully. Here are the details:

ubuntu@:~$ sudo apache2 -v Server version: Apache/2.4.53 (Ubuntu) Server built: 2022-04-28T11:49:35

ubuntu@:~$ sudo apache2ctl -M [Fri Jun 24 20:05:56.107750 2022] [core:trace3] [pid 31567:tid 140409546701760] core.c(3472): Setting LogLevel for all modules to trace8 Loaded Modules: core_module (static) so_module (static) watchdog_module (static) http_module (static) log_config_module (static) logio_module (static) version_module (static) unixd_module (static) access_compat_module (shared) alias_module (shared) auth_basic_module (shared) authn_core_module (shared) authn_file_module (shared) authz_core_module (shared) authz_host_module (shared) authz_user_module (shared) autoindex_module (shared) cgi_module (shared) deflate_module (shared) dir_module (shared) env_module (shared) filter_module (shared) headers_module (shared) http2_module (shared) mime_module (shared) mpm_event_module (shared) negotiation_module (shared) proxy_module (shared) proxy_fcgi_module (shared) proxy_http_module (shared) proxy_http2_module (shared) reqtimeout_module (shared) rewrite_module (shared) setenvif_module (shared) socache_shmcb_module (shared) ssl_module (shared) status_module (shared) unique_id_module (shared)

in file: /etc/apache2/sites-enabled/default-ssl.conf

ProxyPass "/v2" "unix://var/run/wsgi_api.sock|http://127.0.0.1/v2/" ProxyPass "/v3" "h2c://127.0.0.1:9080"

grpc-client is able to successfully communicate with the backend grpc-server (via apache proxy). The only problem is when there is an error generated in grpc-server the same error status, and message isn't sent to the grpc-client via apache. Somehow the client gets only generic error which is rpc error: code = Internal desc = server closed the stream without sending trailers. I have attached a successful and an erroneous case here https://stackoverflow.com/questions/72610431/grpc-client-internal-desc-server-closed-the-stream-without-sending-trailers

If we don't use apache and make gprc-client communicate with the server directly, we don't see any problems and error messages are properly sent to the client.

[icing]

HI @ajain621, thanks for the report.

What I did not find in the logs are the 'http2:' traces from mod_http2 when it supposedly closes/resets the steam. The behaviour about which your client complained. Could you produce those?

[ajain621]

Sure @icing I will reproduce . Is there any specific trace level I need to enable. Currently I am at "LogLevel trace8".

[ajain621]

grpc_client_success_trace6.txt grpc_client_gets_no_proper_err_msg_trace6.txt

Added the architecture diagram, and supported logs. For the log "grpc_client_gets_no_proper_err_msg_trace6.txt" the grpc client sees "rpc error: code = Internal desc = server closed the stream without sending trailers:". The actual error generated by grpc-server which is "Invalid or missing credentials when calling v1 api: CID required." doesn't reach the grpc-client. In my understanding before the "grpc-status" and "grpc-message" headers could reach the client, apache is closing the stream. The log "grpc_client_success_trace6.txt" is of a success case, the grpc-server doesn't encounter any internal error and grpc-client receives the expected data. This log is for a comparison.

Apache is used in this case to terminate TLS and also to reverse proxy to backend servers. Note: if we don't use apache and let grpc-client communicate to grpc-server directly, we don't see this "rpc error: code = Internal desc = server closed the stream without sending trailers:" and the related errors are indeed sent to the grpc-client by the grpc-server.

Due to some architectural evolution the v3 api server is temporarily a wrapper to v2 api server. The v3 api flow is as depicted in the diagram. 1>>2>>3>>4

[icing]

Thanks for the logs! What I see is:

Success:
[19:51:44.110742] [http2] recv FRAME[HEADERS[length=109, hend=1, stream=1, eos=0]], frames=2/3 (r/s)
[19:51:44.111421] [proxy_http2] sent FRAME[HEADERS[length=69, hend=1, stream=3, eos=0]]
[19:51:44.111612] [http2] recv FRAME[DATA[length=5, flags=1, stream=1, padlen=0]], frames=3/3 (r/s)
[19:51:44.127606] [proxy_http2] recv FRAME[HEADERS[length=5, hend=1, stream=3, eos=0]]
[19:51:44.127806] [proxy_http2] recv FRAME[DATA[length=207, flags=0, stream=3, padlen=0]]
[19:51:44.127825] [proxy_http2] recv FRAME[HEADERS[length=3, hend=1, stream=3, eos=1]]
[19:51:44.128208] [http2] sent FRAME[HEADERS[length=194, hend=1, stream=1, eos=0]], frames=4/4 (r/s)
[19:51:44.128245] [http2] sent FRAME[DATA[length=207, flags=0, stream=1, padlen=0]], frames=4/5 (r/s)
[19:51:44.128446] [http2] sent FRAME[HEADERS[length=12, hend=1, stream=1, eos=1]], frames=4/6 (r/s)
[19:51:44.273750] [http2] sent FRAME[GOAWAY[error=0, reason='', last_stream=1]], frames=6/8 (r/s)

Failure:
[19:48:16.191683] [http2] recv FRAME[HEADERS[length=92, hend=1, stream=1, eos=0]], frames=2/3 (r/s)
[19:48:16.191753] [http2] recv FRAME[DATA[length=5, flags=1, stream=1, padlen=0]], frames=3/3 (r/s)
[19:48:16.192732] [proxy_http2] sent FRAME[HEADERS[length=176, hend=1, stream=1, eos=0]]
[19:48:16.202848] [proxy_http2] recv FRAME[HEADERS[length=60, hend=1, stream=1, eos=0]]
[19:48:16.203187] [proxy_http2] recv FRAME[HEADERS[length=71, hend=1, stream=1, eos=1]]
[19:48:16.203691] [http2] sent FRAME[HEADERS[length=269, hend=1, stream=1, eos=0]], frames=4/4 (r/s)
[19:48:16.203714] [http2] sent FRAME[DATA[length=0, flags=1, stream=1, padlen=0]], frames=4/5 (r/s)  <--- wrong!
[19:48:16.359046] [http2] sent FRAME[GOAWAY[error=0, reason='', last_stream=1]], frames=5/7 (r/s)

There is a bug mod_http2 when handling trailers without a body. It send a DATA frame with EOS set. This should not happen, instead a final HEADER frame should be send.

Would I write a patch to fix this, can you build a new mod_http2 and test it on your system?

[ajain621]

Thanks @icing . I will retest with your patch. I have not build mod_http2 from source, but can give it a try.

[ajain621]

@icing let me know when the patch is ready. Thks.

[icing]

Reopening it for confirmation.

Just released v2.0.3 here that can be built against a recent 2.4.x apache, as described in the README.md. I will port the changes into the httpd subversion repository, probably next week.

[icing]

For interest: what version of mod_http2 are you running where the error happens? Should be logged at INFO level on startup. Thanks!

[ajain621]

Thanks for the patch @icing . Here are the version details.

[Sat Jul 02 16:38:46.294477 2022] [ssl:info] [pid 15449:tid 140169775844288] AH01876: mod_ssl/2.4.53 compiled against Server: Apache/2.4.53, Library: OpenSSL/1.1.1 [Sat Jul 02 16:38:46.294509 2022] [http2:info] [pid 15449:tid 140169775844288] AH03090: mod_http2 (v1.15.26, feats=CHPRIO+SHA256+INVHD+DWINS, nghttp2 1.30.0), initializing... [Sat Jul 02 16:38:46.294533 2022] [http2:trace1] [pid 15449:tid 140169775844288] h2_h2.c(439): h2_h2, child_init [Sat Jul 02 16:38:46.294572 2022] [http2:trace1] [pid 15449:tid 140169775844288] h2_switch.c(45): h2_switch init [Sat Jul 02 16:38:46.294911 2022] [proxy_http2:info] [pid 15449:tid 140169775844288] AH03349: mod_proxy_http2 (v1.15.26, nghttp2 1.30.0), initializing...

[ajain621]

@icing I am unable to resolve the following error

checking for nghttp2_session_server_new2 in -lnghttp2... no configure: error: "library nghttp2 not found"

my OS:

Distributor ID: Ubuntu Description: Ubuntu 18.04.6 LTS Release: 18.04 Codename: bionic

[icing]

You need the packages apache2-dev and libnghttp2-dev installed.

[ajain621]

@icing the patch works as expected. I am able to see the correct response and I don't see stream termination without sending trailers error in my grpc client. Thanks a lot for a quick patch. Do you want logs?

[icing]

Thanks for verifying! No logs needed. I added a test case for exactly this behaviour to make sure it does not break again.

To determine the affected versions, it would be good to know the version you had trouble with.

[ajain621]

I had trouble with Apache/2.4.53, mod_http2 (v1.15.26) after your patch, following is the version; mod_proxy_http2 (v2.0.3-git, nghttp2 1.30.0), initializing... Apache/2.4.53 (Ubuntu) OpenSSL/1.1.1 configured

[icing]

Hmm, unable to reproduce the problem on a mod_http2 v1.15.x. I have clear test cases for v2.x that reproduces and where I did the fix. However these tests run fine on an unmodified v1.15.x (as shipped in Apache httpd 2.4.53/54).

Something does not match.

[ajain621]

@icing so you mean the erstwhile version (without this fix) is able to sent trailers?

[icing]

@ajain621 at least, I cannot reproduce the problem there with my test cases. If you could possible test this in your setup and confirm/deny, I either am happy or need to dig deeper.

[mholasek]

I had the same problem. I did the test with the client "evans". The error occured when a header for authentication wasn't correctly. The error was

command call: rpc error: code = Internal desc = server closed the stream without sending trailers

instead of

command call: rpc error: code = Unauthenticated desc = Invalid provider_secret.

We used the version mod_http2 (v1.15.28) on Apache. After updating to mod_http2 (v2.0.3-git), the error no longer occurred and the call worked correctly.

[ajain621]

Thanks for verifying @mholasek. @icing when is next release of apache 2.4.55? I hope it would bundle the latest mod_h2 in it.