envoyproxy / envoyproxy/envoy

Incomplete response when using HTTP2+CONNECT tunneling

Open
#28,329 5 comments 4 reactions 0 assignees View on GitHub
bug no stalebot question
Dominant language
C++
Stars
28.9k
Forks
5.6k
Avg merge
1d 20h
Merged PRs (30d)
428

Description

*Description*:
envoy version: 1.25.6

We are using HTTP2+CONNECT to tunnel TCP connections over an HTTP2 connection. The setup looks like:

client --HTTP--> envoy1 --TCP over HTTP2 tunnel---> envoy2 --HTTP--> server

client makes HTTP 1.1 requests.
envoy1 runs a tcp_proxy filter and multiplex the tcp connection on an HTTP2 stream.
envoy2 runs 2 HCMs. The first HCM demultiplexes the HTTP2 stream and feeds to an internal listener with a second HCM. The second HCM routes the original HTTP request to upstream server.
The server serves large binary content using chunk encoding.

When client makes a request without "Connection: close" header, everything works fine. However, if it makes a request **with** "Connection: close" header, sometimes the response is incomplete - the tail of the response is not received.
With curl an error message shows: **transfer closed with outstanding read data remaining**

I did some investigation here. There are 5 connections involved:
C1: stands for client -> envoy1
C2: stands for envoy1 -> envoy2 external listener [C2.log](https://github.com/envoyproxy/envoy/files/12014736/C2.log)
C3: stands for envoy2 first HCM -> upstream (internal listener) [C3.log](https://github.com/envoyproxy/envoy/files/12014735/C3.log)
C4: stands for downstream (envoy2 first HCM) -> internal listener [C4.log](https://github.com/envoyproxy/envoy/files/12014738/C4.log)
C5: stands for envoy2 second HCM -> server [C5.log](https://github.com/envoyproxy/envoy/files/12014737/C5.log)
*C3 and C4 are physically same connection but logically 2 connections from envoy2 perspective*

From logs, I can tell that C5 received whole response from server and C4 wrote whole response. Also, C3 got the whole response. The problem is though C2 successfully encoded the whole response but C2 failed to write all the data before resetting the stream.
I also did a packet capture at envoy1 side and it shows envoy2 reset the stream thus following DATA frames are not being sent.
![image](https://github.com/envoyproxy/envoy/assets/82434622/d4ec2bb9-da12-4dc1-9c94-940411dc6160)

key logs from C2:
[2023-07-11 12:33:45.331][17][trace][http] [source/common/http/conn_manager_impl.cc:1606] [C2][S4803202076355283748] encoding data via codec (size=16384 end_stream=false)
[2023-07-11 12:33:45.332][17][debug][router] [source/common/router/upstream_request.cc:500] [C2][S4803202076355283748] resetting pool request
[2023-07-11 12:33:45.332][17][trace][http] [source/common/http/conn_manager_impl.cc:1606] [C2][S4803202076355283748] encoding data via codec (size=8597 end_stream=true)
[2023-07-11 12:33:45.332][17][debug][http] [source/common/http/conn_manager_impl.cc:212] [C2][S4803202076355283748] doEndStream() resetting stream
[2023-07-11 12:33:45.332][17][debug][http] [source/common/http/conn_manager_impl.cc:1649] [C2][S4803202076355283748] stream reset
[2023-07-11 12:33:45.332][17][trace][http2] [source/common/http/http2/codec_impl.cc:809] [C2] deferred reset stream
[2023-07-11 12:33:45.332][17][trace][http2] [source/common/http/http2/codec_impl.cc:1316] [C2] about to send frame type=3, flags=0
[2023-07-11 12:33:45.332][17][trace][http2] [source/common/http/http2/codec_impl.cc:1338] [C2] send data: bytes=13
[2023-07-11 12:33:45.332][17][trace][connection] [source/common/network/connection_impl.cc:483] [C2] writing 13 bytes, end_stream false
[2023-07-11 12:33:45.332][17][trace][http2] [source/common/http/http2/codec_impl.cc:1218] [C2] sent frame type=3, stream_id=1, length=4
[2023-07-11 12:33:45.332][17][debug][http2] [source/common/http/http2/codec_impl.cc:1247] [C2] sent reset code=0
[2023-07-11 12:33:45.332][17][debug][http2] [source/common/http/http2/codec_impl.cc:1363] [C2] stream 1 closed: 0

Though log says 'deferred reset stream' but actually there's no delay, it sends the RST immediately, causing nghttp2 to drop pending DATA frames.

Some questions:
1. I see [here](https://github.com/nghttp2/nghttp2/issues/692#issuecomment-248595968) suggested using nghttp2_on_frame_send_callback to ensure DATA being sent before RST. But it seems envoy is not using it. Is there any special reason here?https://github.com/envoyproxy/envoy/blob/bd836c22030b20624142c78fc16773d4bb2e582e/source/common/http/http2/codec_impl.cc#L1231-L1243
2. I do not quite understand the logic of deferred reset stream. It seems to me that if a stream is set to be deferred reset, any send operation on any stream (even not same one) can cause the stream to be reset? Because sendPendingFrames() always iterates over all the deferred reset streams and resets them. Does the 'defer' take effect in fact?
3. (Correct me if this does not make sense) Today when the upstream closes the connection, the stream is reset because stream.filter_manager_.remoteDecodeComplete() is false. It makes sense for normal HTTP2 requests to reset the stream when request is not completed. However,for CONNECT, it's always false unless client ends the tunnel. Also, from CONNECT request perspective, the request is already completed so should we handle it in the same way as normal HTTP2 request completed?

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.