abhins
Reputation: 35
grpc client Internal desc = server closed the stream without sending trailers:
grpc-client <--tls--> apache (http2 modules loaded) <---plain text---> grpc-server
apache version and modules:
~$ apache2 -v
Server version: Apache/2.4.53 (Ubuntu)
Server built: 2022-04-28T11:49:35
~$ sudo apachectl -M
[Tue Jun 14 00:54:22.817444 2022] [core:trace3] [pid 10542:tid 140687390821312] 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)
I am using grpc server as a backend server, reversed proxied by Apache. Apache is used to terminate the TLS connection (added http2 support in apache). Following is the proxy setting:
ProxyPassMatch "^/v3" "h2c://127.0.0.1:9080"
Now if I send a valid grpc client request it is successfully proxied by Apache and the grpc server response is received by the grpc client. But when I try to send a request which evokes some error in grpc server, the grpc server's response is shadowed by Apache with a generic response "server closed the stream without sending trailers:".
Here the server generated an "v1 api server returned an error: CID required." and try to send it as grpc-message but apache somehow didn't sent this error. I would like the client to receive a proper error message of the request but it looks like the stream is terminated well before the trailers are sent.
Logs for case with no error:
[Mon Jun 13 19:18:46.055591 2022] [proxy_http2:trace3] [pid 31167:tid 140575498213120] h2_proxy_session.c(1032): [remote 127.0.0.1:9080] h2_proxy_session(64-1): read from conn
[Mon Jun 13 19:18:46.055608 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(405): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): got status 200
[Mon Jun 13 19:18:46.055614 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): on_header content-type: application/grpc
[Mon Jun 13 19:18:46.055626 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): got header Content-Type: application/grpc
[Mon Jun 13 19:18:46.055631 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): on_header trailer: Grpc-Status
[Mon Jun 13 19:18:46.055636 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): got header Trailer: Grpc-Status
[Mon Jun 13 19:18:46.055640 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): on_header trailer: Grpc-Message
[Mon Jun 13 19:18:46.055644 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): got header Trailer: Grpc-Message
[Mon Jun 13 19:18:46.055648 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): on_header trailer: Grpc-Status-Details-Bin
[Mon Jun 13 19:18:46.055652 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): got header Trailer: Grpc-Status-Details-Bin
[Mon Jun 13 19:18:46.055657 2022] [proxy_http2:debug] [pid 31167:tid 140575498213120] h2_proxy_session.c(269): [remote 127.0.0.1:9080] AH03341: h2_proxy_session(64-1): recv FRAME[HEADERS[length=5, hend=1, stream=3, eos=0]]
[Mon Jun 13 19:18:46.055662 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(1077): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): resuming
[Mon Jun 13 19:18:46.055667 2022] [proxy_http2:debug] [pid 31167:tid 140575498213120] h2_proxy_session.c(1187): [remote 127.0.0.1:9080] AH03345: h2_proxy_session(64-1): transit [WAIT] -- stream resumed --> [BUSY]
[Mon Jun 13 19:18:46.055673 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(500): [client <ip:port>] h2_proxy_stream(64-1-3), header_out after merging
[Mon Jun 13 19:18:46.055677 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(440): [client <ip:port>] h2_proxy_stream(64-1-3), header_out Content-Type: application/grpc
[Mon Jun 13 19:18:46.055682 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(440): [client <ip:port>] h2_proxy_stream(64-1-3), header_out Trailer: Grpc-Status
[Mon Jun 13 19:18:46.055691 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(440): [client <ip:port>] h2_proxy_stream(64-1-3), header_out Trailer: Grpc-Message
[Mon Jun 13 19:18:46.055695 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(440): [client <ip:port>] h2_proxy_stream(64-1-3), header_out Trailer: Grpc-Status-Details-Bin
[Mon Jun 13 19:18:46.055700 2022] [filter:trace2] [pid 31167:tid 140575498213120] mod_filter.c(193): [client <ip:port>] Content-Type condition for 'deflate' did not match: no Content-Type
[Mon Jun 13 19:18:46.055704 2022] [filter:trace2] [pid 31167:tid 140575498213120] mod_filter.c(193): [client <ip:port>] Content-Type condition for 'deflate' did not match: no Content-Type
[Mon Jun 13 19:18:46.055708 2022] [filter:trace2] [pid 31167:tid 140575498213120] mod_filter.c(193): [client <ip:port>] Content-Type condition for 'deflate' did not match: no Content-Type
[Mon Jun 13 19:18:46.055737 2022] [filter:trace2] [pid 31167:tid 140575498213120] mod_filter.c(193): [client <ip:port>] Content-Type condition for 'deflate' did not match: no Content-Type
[Mon Jun 13 19:18:46.055743 2022] [filter:trace2] [pid 31167:tid 140575498213120] mod_filter.c(193): [client <ip:port>] Content-Type condition for 'deflate' did not match: no Content-Type
[Mon Jun 13 19:18:46.055747 2022] [headers:trace2] [pid 31167:tid 140575498213120] mod_headers.c(866): AH01502: headers: ap_headers_output_filter()
[Mon Jun 13 19:18:46.055754 2022] [http2:trace1] [pid 31167:tid 140575498213120] h2_from_h1.c(518): [client <ip:port>] h2_task(65-1): output_filter called
[Mon Jun 13 19:18:46.055767 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_task.c(62): [client <ip:port>] bb_dump(65-1): h2_task send_out(H2HEADERS TRANSIENT[5] FLUSH)
[Mon Jun 13 19:18:46.055772 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_bucket_beam.c(1286): [client <ip:port>] beam(65-1,output,closed=0,aborted=0,empty=1,buf=0): send_out(before)
[Mon Jun 13 19:18:46.055777 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_bucket_beam.c(1286): [client <ip:port>] beam(65-1,output,closed=0,aborted=0,empty=0,buf=313): send_out(after)
[Mon Jun 13 19:18:46.055782 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_task.c(120): [client <ip:port>] h2_task(65-1): send_out done
[Mon Jun 13 19:18:46.055786 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_task.c(192): [client <ip:port>] h2_secondary_out(65-1): buffered=1
[Mon Jun 13 19:18:46.055790 2022] [http2:debug] [pid 31167:tid 140575498213120] h2_task.c(87): [client <ip:port>] AH03348: h2_task(65-1): open output to POST 3.142.47.26:443 /v3/ListG
[Mon Jun 13 19:18:46.055795 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_bucket_beam.c(1286): [client <ip:port>] beam(65-1,output,closed=0,aborted=0,empty=0,buf=313): out_open
[Mon Jun 13 19:18:46.055803 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_task.c(199): [client <ip:port>] h2_secondary_out(65-1): secondary_out leave
[Mon Jun 13 19:18:46.055808 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_task.c(62): [client <ip:port>] bb_dump(65-1): h2_task send_out()
[Mon Jun 13 19:18:46.055812 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_bucket_beam.c(1286): [client <ip:port>] beam(65-1,output,closed=0,aborted=0,empty=0,buf=313): send_out(before)
[Mon Jun 13 19:18:46.055816 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_bucket_beam.c(1286): [client <ip:port>] beam(65-1,output,closed=0,aborted=0,empty=0,buf=313): send_out(after)
[Mon Jun 13 19:18:46.055820 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_task.c(120): [client <ip:port>] h2_task(65-1): send_out done
[Mon Jun 13 19:18:46.055824 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_task.c(192): [client <ip:port>] h2_secondary_out(65-1): buffered=1
[Mon Jun 13 19:18:46.055832 2022] [http2:trace2] [pid 31167:tid 140575498213120] h2_task.c(199): [client <ip:port>] h2_secondary_out(65-1): secondary_out leave
[Mon Jun 13 19:18:46.055836 2022] [proxy_http2:debug] [pid 31167:tid 140575498213120] h2_proxy_session.c(542): [client <ip:port>] AH03359: h2_proxy_session(64-1): stream=3, response DATA 5, 5 total
[Mon Jun 13 19:18:46.055842 2022] [proxy_http2:debug] [pid 31167:tid 140575498213120] h2_proxy_session.c(269): [remote 127.0.0.1:9080] AH03341: h2_proxy_session(64-1): recv FRAME[DATA[length=5, flags=0, stream=3, padlen=0]]
[Mon Jun 13 19:18:46.055850 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): on_header grpc-status: 0
[Mon Jun 13 19:18:46.055854 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): got header Grpc-Status: 0
[Mon Jun 13 19:18:46.055859 2022] [proxy_http2:debug] [pid 31167:tid 140575498213120] h2_proxy_session.c(269): [remote 127.0.0.1:9080] AH03341: h2_proxy_session(64-1): recv FRAME[HEADERS[length=3, hend=1, stream=3, eos=1]]
[Mon Jun 13 19:18:46.055864 2022] [proxy_http2:trace2] [pid 31167:tid 140575498213120] h2_proxy_session.c(1077): [remote 127.0.0.1:9080] h2_proxy_stream(64-1-3): resuming
[Mon Jun 13 19:18:46.055868 2022] [proxy_http2:debug] [pid 31167:tid 140575498213120] h2_proxy_session.c(562): [remote 127.0.0.1:9080] AH03360: h2_proxy_session(64-1): stream=3, closed, err=0
[Mon Jun 13 19:18:46.055922 2022] [proxy_http2:debug] [pid 31167:tid 140575498213120] h2_proxy_session.c(1355): [remote 127.0.0.1:9080] AH03364: h2_proxy_sesssion(64-1): stream(3) closed (touched=1, error=0)
[Mon Jun 13 19:18:46.055926 2022] [proxy_http2:trace1] [pid 31167:tid 140575498213120] mod_proxy_http2.c(213): [client <ip:port>] h2_proxy_session(65-1): request done, touched=1
[Mon Jun 13 19:18:46.055932 2022] [proxy_http2:trace1] [pid 31167:tid 140575498213120] h2_proxy_session.c(977): [remote 127.0.0.1:9080] h2_proxy_session(64-1): feeding 40 bytes -> 40
[Mon Jun 13 19:18:46.055937 2022] [proxy_http2:trace1] [pid 31167:tid 140575498213120] h2_proxy_session.c(996): [remote 127.0.0.1:9080] h2_proxy_session(64-1): fed 40 bytes of input to session
[Mon Jun 13 19:18:46.055947 2022] [proxy:debug] [pid 31167:tid 140575498213120] proxy_util.c(2549): AH00943: H2C: has released connection for (127.0.0.1)
<ip:port>
Logs for case with errors:
[Mon Jun 13 19:20:09.671782 2022] [proxy_http2:trace3] [pid 31166:tid 140575498213120] h2_proxy_session.c(1032): [remote 127.0.0.1:9080] h2_proxy_session(17-1): read from conn
[Mon Jun 13 19:20:09.671795 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(405): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): got status 200
[Mon Jun 13 19:20:09.671800 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): on_header content-type: application/grpc
[Mon Jun 13 19:20:09.671805 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): got header Content-Type: application/grpc
[Mon Jun 13 19:20:09.671810 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): on_header trailer: Grpc-Status
[Mon Jun 13 19:20:09.671815 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): got header Trailer: Grpc-Status
[Mon Jun 13 19:20:09.671819 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): on_header trailer: Grpc-Message
[Mon Jun 13 19:20:09.671823 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): got header Trailer: Grpc-Message
[Mon Jun 13 19:20:09.671827 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): on_header trailer: Grpc-Status-Details-Bin
[Mon Jun 13 19:20:09.671835 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): got header Trailer: Grpc-Status-Details-Bin
[Mon Jun 13 19:20:09.671840 2022] [proxy_http2:debug] [pid 31166:tid 140575498213120] h2_proxy_session.c(269): [remote 127.0.0.1:9080] AH03341: h2_proxy_session(17-1): recv FRAME[HEADERS[length=5, hend=1, stream=3, eos=0]]
[Mon Jun 13 19:20:09.671845 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(1077): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): resuming
[Mon Jun 13 19:20:09.671849 2022] [proxy_http2:debug] [pid 31166:tid 140575498213120] h2_proxy_session.c(1187): [remote 127.0.0.1:9080] AH03345: h2_proxy_session(17-1): transit [WAIT] -- stream resumed --> [BUSY]
[Mon Jun 13 19:20:09.671858 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): on_header grpc-message: v1 api server returned an error: CID required.
[Mon Jun 13 19:20:09.671863 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): got header Grpc-Message: v1 api server returned an error: CID required.
[Mon Jun 13 19:20:09.671868 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(417): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): on_header grpc-status: 13
[Mon Jun 13 19:20:09.671872 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(429): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): got header Grpc-Status: 13
[Mon Jun 13 19:20:09.671877 2022] [proxy_http2:debug] [pid 31166:tid 140575498213120] h2_proxy_session.c(269): [remote 127.0.0.1:9080] AH03341: h2_proxy_session(17-1): recv FRAME[HEADERS[length=51, hend=1, stream=3, eos=1]]
[Mon Jun 13 19:20:09.671881 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(1077): [remote 127.0.0.1:9080] h2_proxy_stream(17-1-3): resuming
[Mon Jun 13 19:20:09.671890 2022] [proxy_http2:debug] [pid 31166:tid 140575498213120] h2_proxy_session.c(562): [remote 127.0.0.1:9080] AH03360: h2_proxy_session(17-1): stream=3, closed, err=0
[Mon Jun 13 19:20:09.671894 2022] [proxy_http2:debug] [pid 31166:tid 140575498213120] h2_proxy_session.c(1355): [remote 127.0.0.1:9080] AH03364: h2_proxy_sesssion(17-1): stream(3) closed (touched=1, error=0)
[Mon Jun 13 19:20:09.671899 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(500): [client <ip:port>] h2_proxy_stream(17-1-3), header_out after merging
[Mon Jun 13 19:20:09.671903 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(440): [client <ip:port>] h2_proxy_stream(17-1-3), header_out Content-Type: application/grpc
[Mon Jun 13 19:20:09.671908 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(440): [client <ip:port>] h2_proxy_stream(17-1-3), header_out Trailer: Grpc-Status
[Mon Jun 13 19:20:09.671912 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(440): [client <ip:port>] h2_proxy_stream(17-1-3), header_out Trailer: Grpc-Message
[Mon Jun 13 19:20:09.671915 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(440): [client <ip:port>] h2_proxy_stream(17-1-3), header_out Trailer: Grpc-Status-Details-Bin
[Mon Jun 13 19:20:09.671919 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(440): [client <ip:port>] h2_proxy_stream(17-1-3), header_out Grpc-Message: v1 api server returned an error: CID required.
[Mon Jun 13 19:20:09.671924 2022] [proxy_http2:trace2] [pid 31166:tid 140575498213120] h2_proxy_session.c(440): [client <ip:port>] h2_proxy_stream(17-1-3), header_out Grpc-Status: 13
[Mon Jun 13 19:20:09.671929 2022] [filter:trace2] [pid 31166:tid 140575498213120] mod_filter.c(193): [client <ip:port>] Content-Type condition for 'deflate' did not match: no Content-Type
[Mon Jun 13 19:20:09.671933 2022] [filter:trace2] [pid 31166:tid 140575498213120] mod_filter.c(193): [client <ip:port>] Content-Type condition for 'deflate' did not match: no Content-Type
[Mon Jun 13 19:20:09.671937 2022] [filter:trace2] [pid 31166:tid 140575498213120] mod_filter.c(193): [client <ip:port>] Content-Type condition for 'deflate' did not match: no Content-Type
[Mon Jun 13 19:20:09.671941 2022] [filter:trace2] [pid 31166:tid 140575498213120] mod_filter.c(193): [client <ip:port>] Content-Type condition for 'deflate' did not match: no Content-Type
[Mon Jun 13 19:20:09.671945 2022] [filter:trace2] [pid 31166:tid 140575498213120] mod_filter.c(193): [client <ip:port>] Content-Type condition for 'deflate' did not match: no Content-Type
[Mon Jun 13 19:20:09.671949 2022] [headers:trace2] [pid 31166:tid 140575498213120] mod_headers.c(866): AH01502: headers: ap_headers_output_filter()
[Mon Jun 13 19:20:09.671957 2022] [http2:trace1] [pid 31166:tid 140575498213120] h2_from_h1.c(518): [client <ip:port>] h2_task(21-1): output_filter called
[Mon Jun 13 19:20:09.671970 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_task.c(62): [client <ip:port>] bb_dump(21-1): h2_task send_out(FLUSH H2HEADERS EOS)
[Mon Jun 13 19:20:09.671975 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_bucket_beam.c(1286): [client <ip:port>] beam(21-1,output,closed=0,aborted=0,empty=1,buf=0): send_out(before)
[Mon Jun 13 19:20:09.671981 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_bucket_beam.c(1286): [client <ip:port>] beam(21-1,output,closed=1,aborted=0,empty=0,buf=394): send_out(after)
[Mon Jun 13 19:20:09.671985 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_task.c(120): [client <ip:port>] h2_task(21-1): send_out done
[Mon Jun 13 19:20:09.671989 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_task.c(192): [client <ip:port>] h2_secondary_out(21-1): buffered=1
[Mon Jun 13 19:20:09.671993 2022] [http2:debug] [pid 31166:tid 140575498213120] h2_task.c(87): [client <ip:port>] AH03348: h2_task(21-1): open output to POST 3.142.47.26:443 /v3/ListG
[Mon Jun 13 19:20:09.672001 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_bucket_beam.c(1286): [client <ip:port>] beam(21-1,output,closed=1,aborted=0,empty=0,buf=394): out_open
[Mon Jun 13 19:20:09.672017 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_task.c(199): [client <ip:port>] h2_secondary_out(21-1): secondary_out leave
[Mon Jun 13 19:20:09.672023 2022] [proxy_http2:trace1] [pid 31166:tid 140575498213120] mod_proxy_http2.c(213): [client <ip:port>] h2_proxy_session(21-1): request done, touched=1
[Mon Jun 13 19:20:09.672028 2022] [proxy_http2:trace1] [pid 31166:tid 140575498213120] h2_proxy_session.c(977): [remote 127.0.0.1:9080] h2_proxy_session(17-1): feeding 74 bytes -> 74
[Mon Jun 13 19:20:09.672025 2022] [http2:trace2] [pid 31166:tid 140575034513152] h2_mplx.c(600): [client <ip:port>] h2_mplx(21): trywait on data for 2.560000 ms)
[Mon Jun 13 19:20:09.672033 2022] [proxy_http2:trace1] [pid 31166:tid 140575498213120] h2_proxy_session.c(996): [remote 127.0.0.1:9080] h2_proxy_session(17-1): fed 74 bytes of input to session
[Mon Jun 13 19:20:09.672039 2022] [http2:trace1] [pid 31166:tid 140575034513152] h2_session.c(1704): [client <ip:port>] AH03078: h2_session(21,BUSY,1): transit [WAIT] -- stream change --> [BUSY]
[Mon Jun 13 19:20:09.672041 2022] [proxy:debug] [pid 31166:tid 140575498213120] proxy_util.c(2549): AH00943: H2C: has released connection for (127.0.0.1)
[Mon Jun 13 19:20:09.672047 2022] [http2:trace1] [pid 31166:tid 140575034513152] h2_filter.c(146): [client <ip:port>] h2_session(21): read, NONBLOCK_READ, mode=0, readbytes=65536
[Mon Jun 13 19:20:09.672049 2022] [proxy_http2:debug] [pid 31166:tid 140575498213120] mod_proxy_http2.c(442): [client <ip:port>] AH03377: leaving handler
[Mon Jun 13 19:20:09.672057 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_task.c(62): [client <ip:port>] bb_dump(21-1): h2_task send_out(EOR)
[Mon Jun 13 19:20:09.672060 2022] [ssl:trace4] [pid 31166:tid 140575034513152] ssl_engine_io.c(2406): [client <ip:port>] OpenSSL: read 0/5 bytes from BIO#7fda10003150 [mem: 7fda10012df3] (BIO dump follows)
[Mon Jun 13 19:20:09.672062 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_bucket_beam.c(1286): [client <ip:port>] beam(21-1,output,closed=1,aborted=0,empty=0,buf=394): send_out(before)
[Mon Jun 13 19:20:09.672066 2022] [ssl:trace7] [pid 31166:tid 140575034513152] ssl_engine_io.c(2332): [client <ip:port>] +-------------------------------------------------------------------------+
[Mon Jun 13 19:20:09.672069 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_bucket_beam.c(1286): [client <ip:port>] beam(21-1,output,closed=1,aborted=0,empty=0,buf=394): send_out(after)
[Mon Jun 13 19:20:09.672071 2022] [ssl:trace7] [pid 31166:tid 140575034513152] ssl_engine_io.c(2374): [client <ip:port>] +-------------------------------------------------------------------------+
[Mon Jun 13 19:20:09.672074 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_task.c(120): [client <ip:port>] h2_task(21-1): send_out done
[Mon Jun 13 19:20:09.672078 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_task.c(192): [client <ip:port>] h2_secondary_out(21-1): buffered=1
[Mon Jun 13 19:20:09.672077 2022] [http2:trace1] [pid 31166:tid 140575034513152] h2_filter.c(191): (11)Resource temporarily unavailable: [client <ip:port>] h2_session(21): read
[Mon Jun 13 19:20:09.672082 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_task.c(199): [client <ip:port>] h2_secondary_out(21-1): secondary_out leave
[Mon Jun 13 19:20:09.672085 2022] [http2:trace2] [pid 31166:tid 140575034513152] h2_mplx.c(1096): [client <ip:port>] h2_mplx(21): dispatch events
[Mon Jun 13 19:20:09.672088 2022] [http2:trace2] [pid 31166:tid 140575498213120] h2_task.c(62): [client <ip:port>] bb_dump(21-1): h2_task send_out(FLUSH)
Upvotes: 0
Views: 2468
Answers (1)
icing
Reputation: 26
"apache somehow didn't sent this error."
I do not see in you logs what exactly apache sent back to your client. I do see that the mod_proxy_http2 seems to have processed the request to the backend correctly.
Could you open an issue at https://github.com/icing/mod_h2? Let's have the discussion there.
Upvotes: 1
Related Questions
- How to use grpc bidirectional streaming in grpc-web?
- gRPC Server-side non-streaming request
- /* in transcoding from HTTP to gRPC
- How to use grpc streaming in grpc-web?
- Be sure that a gRPC bi-directional streaming message is arrived to the client
- gRpc bidirectional stream
- Java gRPC: exception from client to server
- grpc streaming over reverse proxy
- Web client communicate with gRPC server
- Using gRPC over the Internet