Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Envoy returns Message: stream timeout without handling pending gRPC requests when max_requests_per_connection is set #36712

Open
toyamagu-2021 opened this issue Oct 20, 2024 · 3 comments
Open

Envoy returns Message: stream timeout without handling pending gRPC requests when max_requests_per_connection is set #36712

toyamagu-2021 opened this issue Oct 20, 2024 · 3 comments
Labels
area/http

Comments

@toyamagu-2021
Copy link

toyamagu-2021 commented Oct 20, 2024 •
edited
Loading

Title: Envoy returns Message: stream timeout without handling pending gRPC requests when max_requests_per_connection is set

Expectation

I think Envoy should handle all requests without timeout in the following situation.

  1. 1 gRPC connection, 1 host
  2. limited amount of max_requests_per_connection
  3. When large number of requests comes in, some are sent to upstream and others are "pending request" by max_requests_per_connection.
  4. Preceded requests handled, "pending requests" are sent to upstream and handled sequentially.
  5. timeout is large enough, all requests are handled.

But pending request are not handled, I've got timeout error.

Experimental Situation

The detailed settings are attached in the last section:

  1. Keep 1 connection per host using a circuit breaker.
  2. max_requests_per_connection: 2 and max_concurrent_streams: 20
    • I've tried various combinations of the above parameters, but the same error occurred, except with large max_requests_per_connection and max_concurrent_streams.
  3. The backend Go server responds in 10 second (I've used podinfo for experimental purposes, but not important.).
  4. idle_timeout: 30s and timeout: 0s
    • Actually, 30s is not important. I reproduced this timeout: 5min.
  5. Send requests approximately 4 times to Envoy.

First 1~3 requests handled successfully, but other request shows following timeout

Command:

for i in $(seq 1 5)
do
  echo $i
  time /root/go/bin/grpcurl -plaintext -d '{"seconds":10}' envoy:10000 delay.DelayService/Delay &
done

Log:

real    0m 10.05s
user    0m 0.00s
sys     0m 0.00s
real    0m 10.07s
user    0m 0.00s
sys     0m 0.00s
real    0m 10.05s
user    0m 0.00s
sys     0m 0.00s
real    0m 10.07s
user    0m 0.00s
sys     0m 0.00s
Done                       time /root/go/bin/grpcurl -plaintext -d "{\"seconds\":10}" envoy:10000 delay.DelayService/Delay
Done                       time /root/go/bin/grpcurl -plaintext -d "{\"seconds\":10}" envoy:10000 delay.DelayService/Delay
Done                       time /root/go/bin/grpcurl -plaintext -d "{\"seconds\":10}" envoy:10000 delay.DelayService/Delay
/ # ERROR:
  Code: Unavailable
  Message: stream timeout
Command exited with non-zero status 78
real    0m 30.05s
user    0m 0.00s
sys     0m 0.00s

We can see three requests handle parallel in 10s as expected.
My expectation is request 4th should be handled because previous three requests finished.
Or this is expected behaviours by design?

[optional Relevant Links:]

Any extra documentation required to understand the issue.

Envoy Settings 
      clusters:
      - name: podinfo
        connect_timeout: 0.25s
        type: STRICT_DNS
        dns_lookup_family: V4_ONLY
        lb_policy: ROUND_ROBIN
        typed_extension_protocol_options:
          envoy.extensions.upstreams.http.v3.HttpProtocolOptions:
            "@type": type.googleapis.com/envoy.extensions.upstreams.http.v3.HttpProtocolOptions
            common_http_protocol_options:
              max_requests_per_connection: 2
            explicit_http_config:
              http2_protocol_options:
                max_concurrent_streams: 20
        circuit_breakers:
          thresholds:
            max_connections: 100
            max_requests: 20
            max_pending_requests: 100
          per_host_thresholds:
            max_connections: 1
        ignore_health_on_host_removal: true
        load_assignment:
          cluster_name: podinfo
          endpoints:
          - lb_endpoints:
            - endpoint:
                address:
                  socket_address:
                    address: podinfo
                    port_value: 9999
Envoy log for timeout request

start request

envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.646][24][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"275"] new connection from 10.244.0.11:59834
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.646][24][debug][http2] [source/common/http/http2/codec_impl.cc:1696] [Tags: "ConnectionId":"275"] updating connection-level initial window size to 268435456
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.646][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(0, 0, 4, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.647][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(0, 0, 4, 1)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(1, 137, 1, 4)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][http] [source/common/http/conn_manager_impl.cc:385] [Tags: "ConnectionId":"275"] new stream
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][http2] [source/common/http/http2/codec_impl.cc:1847] [Tags: "ConnectionId":"275"] Http2Visitor::OnEndHeadersForStream(1)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][http] [source/common/http/conn_manager_impl.cc:1135] [Tags: "ConnectionId":"275","StreamId":"11498334530499678467"] request headers complete (end_stream=false):
envoy-5575cc449d-mkc8s envoy ':method', 'POST'
envoy-5575cc449d-mkc8s envoy ':scheme', 'http'
envoy-5575cc449d-mkc8s envoy ':path', '/grpc.reflection.v1.ServerReflection/ServerReflectionInfo'
envoy-5575cc449d-mkc8s envoy ':authority', 'envoy:10000'
envoy-5575cc449d-mkc8s envoy 'content-type', 'application/grpc'
envoy-5575cc449d-mkc8s envoy 'user-agent', 'grpcurl/dev-build (no version set) grpc-go/1.61.0'
envoy-5575cc449d-mkc8s envoy 'te', 'trailers'
envoy-5575cc449d-mkc8s envoy 'grpc-accept-encoding', 'gzip'
envoy-5575cc449d-mkc8s envoy 
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"275"] current connecting state: false
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][router] [source/common/router/router.cc:525] [Tags: "ConnectionId":"275","StreamId":"11498334530499678467"] cluster 'podinfo' match for URL '/grpc.reflection.v1.ServerReflection/ServerReflectionInfo'
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][router] [source/common/router/router.cc:750] [Tags: "ConnectionId":"275","StreamId":"11498334530499678467"] router decoding headers:
envoy-5575cc449d-mkc8s envoy ':method', 'POST'
envoy-5575cc449d-mkc8s envoy ':scheme', 'http'
envoy-5575cc449d-mkc8s envoy ':path', '/grpc.reflection.v1.ServerReflection/ServerReflectionInfo'
envoy-5575cc449d-mkc8s envoy ':authority', 'envoy:10000'
envoy-5575cc449d-mkc8s envoy 'content-type', 'application/grpc'
envoy-5575cc449d-mkc8s envoy 'user-agent', 'grpcurl/dev-build (no version set) grpc-go/1.61.0'
envoy-5575cc449d-mkc8s envoy 'te', 'trailers'
envoy-5575cc449d-mkc8s envoy 'grpc-accept-encoding', 'gzip'
envoy-5575cc449d-mkc8s envoy 'x-forwarded-proto', 'http'
envoy-5575cc449d-mkc8s envoy 'x-request-id', '7c4388ed-caa8-4dfa-8cce-aa8819957210'
envoy-5575cc449d-mkc8s envoy 'x-envoy-original-path', '/grpc.reflection.v1.ServerReflection/ServerReflectionInfo'
envoy-5575cc449d-mkc8s envoy 
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][pool] [source/common/http/conn_pool_base.cc:78] queueing stream due to no available connections (ready=0 busy=1 connecting=0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:291] trying to create new connection
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(1, 25, 0, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][http2] [source/common/http/http2/codec_impl.cc:1855] [Tags: "ConnectionId":"275"] Http2Visitor::OnBeginDataForStream(1, 25)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][http2] [source/common/http/http2/codec_impl.cc:1867] [Tags: "ConnectionId":"275"] Http2Visitor: remaining data payload: 25, end_stream: false
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:36:42.648][24][debug][http2] [source/common/http/http2/codec_impl.cc:1896] [Tags: "ConnectionId":"275"] Http2Visitor dispatching DATA for stream 1

after tiimeout

envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.351][24][debug][http] [source/common/http/filter_manager.cc:1014] [Tags: "ConnectionId":"271","StreamId":"1166513733725662613"] Resetting stream due to stream_idle_timeout. Prior headers have already been sent
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.351][24][debug][http] [source/common/http/conn_manager_impl.cc:250] [Tags: "ConnectionId":"271","StreamId":"1166513733725662613"] doEndStream() resetting stream
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.351][24][debug][http] [source/common/http/conn_manager_impl.cc:1894] [Tags: "ConnectionId":"271","StreamId":"1166513733725662613"] stream reset: reset reason: local reset, response details: -
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.351][24][debug][router] [source/common/router/upstream_request.cc:493] [Tags: "ConnectionId":"271","StreamId":"1166513733725662613"] resetting pool request
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.351][24][debug][client] [source/common/http/codec_client.cc:159] [Tags: "ConnectionId":"42"] request reset
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.351][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:215] [Tags: "ConnectionId":"42"] destroying stream: 0 remaining
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"42"] closing data_to_write=0 type=1
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"42"] closing socket: 1
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][client] [source/common/http/codec_client.cc:107] [Tags: "ConnectionId":"42"] disconnect. resetting 0 pending requests
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:495] [Tags: "ConnectionId":"42"] client disconnected, failure reason: 
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:145] creating a new connection (connecting=0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][http2] [source/common/http/http2/codec_impl.cc:1696] [Tags: "ConnectionId":"285"] updating connection-level initial window size to 268435456
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"285"] current connecting state: true
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][client] [source/common/http/codec_client.cc:57] [Tags: "ConnectionId":"285"] connecting
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][connection] [source/common/network/connection_impl.cc:1017] [Tags: "ConnectionId":"285"] connecting to 10.96.201.147:9999
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][connection] [source/common/network/connection_impl.cc:1036] [Tags: "ConnectionId":"285"] connection in progress
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][http2] [source/common/http/http2/codec_impl.cc:1293] [Tags: "ConnectionId":"271"] sent reset code=0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][http2] [source/common/http/http2/codec_impl.cc:1445] [Tags: "ConnectionId":"271"] stream 1 closed: 0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][http2] [source/common/http/http2/codec_impl.cc:1508] [Tags: "ConnectionId":"271"] Recouping 0 bytes of flow control window for stream 1.
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.352][24][debug][http2] [source/common/http/http2/codec_impl.cc:1930] [Tags: "ConnectionId":"271"] Http2Visitor invoking stream close listener for 1
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.353][24][debug][connection] [source/common/network/connection_impl.cc:746] [Tags: "ConnectionId":"285"] connected
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.353][24][debug][client] [source/common/http/codec_client.cc:88] [Tags: "ConnectionId":"285"] connected
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.353][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:328] [Tags: "ConnectionId":"285"] attaching to next stream
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.353][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:182] [Tags: "ConnectionId":"285"] creating stream
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.353][24][debug][router] [source/common/router/upstream_request.cc:595] [Tags: "ConnectionId":"271","StreamId":"14557094635673299574"] pool ready
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.353][24][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"285"] encode complete
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.353][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:328] [Tags: "ConnectionId":"285"] attaching to next stream
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.353][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:182] [Tags: "ConnectionId":"285"] creating stream
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.353][24][debug][router] [source/common/router/upstream_request.cc:595] [Tags: "ConnectionId":"275","StreamId":"11498334530499678467"] pool ready
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.357][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(0, 6, 4, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.357][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(0, 0, 4, 1)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.357][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(0, 4, 8, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.357][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(0, 8, 6, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.357][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(3, 14, 1, 4)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.357][24][debug][http2] [source/common/http/http2/codec_impl.cc:1847] [Tags: "ConnectionId":"285"] Http2Visitor::OnEndHeadersForStream(3)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.357][24][debug][router] [source/common/router/router.cc:1551] [Tags: "ConnectionId":"275","StreamId":"11498334530499678467"] upstream headers complete: end_stream=false
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.357][24][debug][http] [source/common/http/conn_manager_impl.cc:1825] [Tags: "ConnectionId":"275","StreamId":"11498334530499678467"] encoding headers via codec (end_stream=false):
envoy-5575cc449d-mkc8s envoy ':status', '200'
envoy-5575cc449d-mkc8s envoy 'content-type', 'application/grpc'
envoy-5575cc449d-mkc8s envoy 'date', 'Sun, 20 Oct 2024 16:37:11 GMT'
envoy-5575cc449d-mkc8s envoy 'server', 'envoy'
envoy-5575cc449d-mkc8s envoy 
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(3, 233, 0, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1855] [Tags: "ConnectionId":"285"] Http2Visitor::OnBeginDataForStream(3, 233)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1867] [Tags: "ConnectionId":"285"] Http2Visitor: remaining data payload: 233, end_stream: false
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1896] [Tags: "ConnectionId":"285"] Http2Visitor dispatching DATA for stream 3
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http] [source/common/http/filter_manager.cc:1075] [Tags: "ConnectionId":"271","StreamId":"14557094635673299574"] Sending local reply with details stream_idle_timeout
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http] [source/common/http/conn_manager_impl.cc:1825] [Tags: "ConnectionId":"271","StreamId":"14557094635673299574"] encoding headers via codec (end_stream=true):
envoy-5575cc449d-mkc8s envoy ':status', '200'
envoy-5575cc449d-mkc8s envoy 'content-type', 'application/grpc'
envoy-5575cc449d-mkc8s envoy 'grpc-status', '14'
envoy-5575cc449d-mkc8s envoy 'grpc-message', 'stream timeout'
envoy-5575cc449d-mkc8s envoy 'date', 'Sun, 20 Oct 2024 16:37:11 GMT'
envoy-5575cc449d-mkc8s envoy 'server', 'envoy'
envoy-5575cc449d-mkc8s envoy 
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http] [source/common/http/conn_manager_impl.cc:1937] [Tags: "ConnectionId":"271","StreamId":"14557094635673299574"] Codec completed encoding stream.
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1445] [Tags: "ConnectionId":"271"] stream 3 closed: 0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1508] [Tags: "ConnectionId":"271"] Recouping 0 bytes of flow control window for stream 3.
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1930] [Tags: "ConnectionId":"271"] Http2Visitor invoking stream close listener for 3
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][router] [source/common/router/upstream_request.cc:493] [Tags: "ConnectionId":"271","StreamId":"14557094635673299574"] resetting pool request
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][client] [source/common/http/codec_client.cc:159] [Tags: "ConnectionId":"285"] request reset
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:215] [Tags: "ConnectionId":"285"] destroying stream: 1 remaining
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1293] [Tags: "ConnectionId":"285"] sent reset code=0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1445] [Tags: "ConnectionId":"285"] stream 1 closed: 0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1508] [Tags: "ConnectionId":"285"] Recouping 0 bytes of flow control window for stream 1.
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.358][24][debug][http2] [source/common/http/http2/codec_impl.cc:1930] [Tags: "ConnectionId":"285"] Http2Visitor invoking stream close listener for 1
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.362][24][debug][connection] [source/common/network/connection_impl.cc:714] [Tags: "ConnectionId":"271"] remote close
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.362][24][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"271"] closing socket: 0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.363][24][debug][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"271"] adding to cleanup list
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.363][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(0, 4, 8, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.363][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(0, 8, 6, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.363][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(3, 28, 1, 4)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http] [source/common/http/conn_manager_impl.cc:385] [Tags: "ConnectionId":"275"] new stream
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http2] [source/common/http/http2/codec_impl.cc:1847] [Tags: "ConnectionId":"275"] Http2Visitor::OnEndHeadersForStream(3)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http] [source/common/http/conn_manager_impl.cc:1135] [Tags: "ConnectionId":"275","StreamId":"1106665781191118731"] request headers complete (end_stream=false):
envoy-5575cc449d-mkc8s envoy ':method', 'POST'
envoy-5575cc449d-mkc8s envoy ':scheme', 'http'
envoy-5575cc449d-mkc8s envoy ':path', '/delay.DelayService/Delay'
envoy-5575cc449d-mkc8s envoy ':authority', 'envoy:10000'
envoy-5575cc449d-mkc8s envoy 'content-type', 'application/grpc'
envoy-5575cc449d-mkc8s envoy 'user-agent', 'grpcurl/dev-build (no version set) grpc-go/1.61.0'
envoy-5575cc449d-mkc8s envoy 'te', 'trailers'
envoy-5575cc449d-mkc8s envoy 'grpc-accept-encoding', 'gzip'
envoy-5575cc449d-mkc8s envoy 
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"275"] current connecting state: false
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][router] [source/common/router/router.cc:525] [Tags: "ConnectionId":"275","StreamId":"1106665781191118731"] cluster 'podinfo' match for URL '/delay.DelayService/Delay'
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][router] [source/common/router/router.cc:750] [Tags: "ConnectionId":"275","StreamId":"1106665781191118731"] router decoding headers:
envoy-5575cc449d-mkc8s envoy ':method', 'POST'
envoy-5575cc449d-mkc8s envoy ':scheme', 'http'
envoy-5575cc449d-mkc8s envoy ':path', '/delay.DelayService/Delay'
envoy-5575cc449d-mkc8s envoy ':authority', 'envoy:10000'
envoy-5575cc449d-mkc8s envoy 'content-type', 'application/grpc'
envoy-5575cc449d-mkc8s envoy 'user-agent', 'grpcurl/dev-build (no version set) grpc-go/1.61.0'
envoy-5575cc449d-mkc8s envoy 'te', 'trailers'
envoy-5575cc449d-mkc8s envoy 'grpc-accept-encoding', 'gzip'
envoy-5575cc449d-mkc8s envoy 'x-forwarded-proto', 'http'
envoy-5575cc449d-mkc8s envoy 'x-request-id', '32a6683b-6e38-450f-b4b6-b53483efc6b1'
envoy-5575cc449d-mkc8s envoy 'x-envoy-original-path', '/delay.DelayService/Delay'
envoy-5575cc449d-mkc8s envoy 
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:265] [Tags: "ConnectionId":"285"] using existing fully connected connection
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:182] [Tags: "ConnectionId":"285"] creating stream
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][router] [source/common/router/upstream_request.cc:595] [Tags: "ConnectionId":"275","StreamId":"1106665781191118731"] pool ready
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(3, 7, 0, 1)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http2] [source/common/http/http2/codec_impl.cc:1855] [Tags: "ConnectionId":"275"] Http2Visitor::OnBeginDataForStream(3, 7)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http2] [source/common/http/http2/codec_impl.cc:1867] [Tags: "ConnectionId":"275"] Http2Visitor: remaining data payload: 7, end_stream: true
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http2] [source/common/http/http2/codec_impl.cc:1903] [Tags: "ConnectionId":"275"] Http2Visitor: remaining data payload: 0, end_stream: true
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http2] [source/common/http/http2/codec_impl.cc:1908] [Tags: "ConnectionId":"275"] Http2Visitor::OnEndStream(3)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http2] [source/common/http/http2/codec_impl.cc:1913] [Tags: "ConnectionId":"275"] Http2Visitor dispatching DATA for stream 3
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http] [source/common/http/conn_manager_impl.cc:1118] [Tags: "ConnectionId":"275","StreamId":"1106665781191118731"] request end stream
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"285"] encode complete
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(0, 4, 8, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:11.364][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(0, 8, 6, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20T16:36:41.350Z] "POST /grpc.reflection.v1.ServerReflection/ServerReflectionInfo HTTP/2" 200 SI 25 233 30001 - "-" "grpcurl/dev-build (no version set) grpc-go/1.61.0" "ab1eb381-573c-4b9d-89dd-93a8e4352f51" "envoy:10000" "10.96.201.147:9999"
envoy-5575cc449d-mkc8s envoy [2024-10-20T16:36:41.356Z] "POST /delay.DelayService/Delay HTTP/2" 200 SI 7 0 30001 - "-" "grpcurl/dev-build (no version set) grpc-go/1.61.0" "988224d2-31df-4fac-bf2b-d9fc5862fbce" "envoy:10000" "10.96.201.147:9999"
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(5, 2, 1, 4)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][http2] [source/common/http/http2/codec_impl.cc:1847] [Tags: "ConnectionId":"285"] Http2Visitor::OnEndHeadersForStream(5)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][router] [source/common/router/router.cc:1551] [Tags: "ConnectionId":"275","StreamId":"1106665781191118731"] upstream headers complete: end_stream=false
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][http] [source/common/http/conn_manager_impl.cc:1825] [Tags: "ConnectionId":"275","StreamId":"1106665781191118731"] encoding headers via codec (end_stream=false):
envoy-5575cc449d-mkc8s envoy ':status', '200'
envoy-5575cc449d-mkc8s envoy 'content-type', 'application/grpc'
envoy-5575cc449d-mkc8s envoy 'x-envoy-upstream-service-time', '10001'
envoy-5575cc449d-mkc8s envoy 'date', 'Sun, 20 Oct 2024 16:37:21 GMT'
envoy-5575cc449d-mkc8s envoy 'server', 'envoy'
envoy-5575cc449d-mkc8s envoy 
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(5, 7, 0, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][http2] [source/common/http/http2/codec_impl.cc:1855] [Tags: "ConnectionId":"285"] Http2Visitor::OnBeginDataForStream(5, 7)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][http2] [source/common/http/http2/codec_impl.cc:1867] [Tags: "ConnectionId":"285"] Http2Visitor: remaining data payload: 7, end_stream: false
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][http2] [source/common/http/http2/codec_impl.cc:1896] [Tags: "ConnectionId":"285"] Http2Visitor dispatching DATA for stream 5
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(5, 24, 1, 5)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][http2] [source/common/http/http2/codec_impl.cc:1847] [Tags: "ConnectionId":"285"] Http2Visitor::OnEndHeadersForStream(5)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][client] [source/common/http/codec_client.cc:129] [Tags: "ConnectionId":"285"] response complete
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.365][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:215] [Tags: "ConnectionId":"285"] destroying stream: 1 remaining
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.366][24][debug][http] [source/common/http/conn_manager_impl.cc:1855] [Tags: "ConnectionId":"275","StreamId":"1106665781191118731"] encoding trailers via codec:
envoy-5575cc449d-mkc8s envoy 'grpc-status', '0'
envoy-5575cc449d-mkc8s envoy 'grpc-message', ''
envoy-5575cc449d-mkc8s envoy 
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.366][24][debug][http] [source/common/http/conn_manager_impl.cc:1937] [Tags: "ConnectionId":"275","StreamId":"1106665781191118731"] Codec completed encoding stream.
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.366][24][debug][http2] [source/common/http/http2/codec_impl.cc:1445] [Tags: "ConnectionId":"275"] stream 3 closed: 0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.366][24][debug][http2] [source/common/http/http2/codec_impl.cc:1508] [Tags: "ConnectionId":"275"] Recouping 0 bytes of flow control window for stream 3.
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.366][24][debug][http2] [source/common/http/http2/codec_impl.cc:1930] [Tags: "ConnectionId":"275"] Http2Visitor invoking stream close listener for 3
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.366][24][debug][http2] [source/common/http/http2/codec_impl.cc:1908] [Tags: "ConnectionId":"285"] Http2Visitor::OnEndStream(5)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.366][24][debug][http2] [source/common/http/http2/codec_impl.cc:1445] [Tags: "ConnectionId":"285"] stream 5 closed: 0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.366][24][debug][http2] [source/common/http/http2/codec_impl.cc:1508] [Tags: "ConnectionId":"285"] Recouping 0 bytes of flow control window for stream 5.
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.366][24][debug][http2] [source/common/http/http2/codec_impl.cc:1930] [Tags: "ConnectionId":"285"] Http2Visitor invoking stream close listener for 5
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.367][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(0, 4, 8, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.367][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(0, 8, 6, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.367][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"275"] Http2Visitor::OnFrameHeader(1, 0, 0, 1)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.367][24][debug][http2] [source/common/http/http2/codec_impl.cc:1855] [Tags: "ConnectionId":"275"] Http2Visitor::OnBeginDataForStream(1, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.367][24][debug][http2] [source/common/http/http2/codec_impl.cc:1867] [Tags: "ConnectionId":"275"] Http2Visitor: remaining data payload: 0, end_stream: true
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.367][24][debug][http2] [source/common/http/http2/codec_impl.cc:1908] [Tags: "ConnectionId":"275"] Http2Visitor::OnEndStream(1)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.367][24][debug][http2] [source/common/http/http2/codec_impl.cc:1913] [Tags: "ConnectionId":"275"] Http2Visitor dispatching DATA for stream 1
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.367][24][debug][http] [source/common/http/conn_manager_impl.cc:1118] [Tags: "ConnectionId":"275","StreamId":"11498334530499678467"] request end stream
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.367][24][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"285"] encode complete
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(0, 8, 6, 0)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http2] [source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"285"] Http2Visitor::OnFrameHeader(3, 2, 1, 5)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http2] [source/common/http/http2/codec_impl.cc:1847] [Tags: "ConnectionId":"285"] Http2Visitor::OnEndHeadersForStream(3)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][client] [source/common/http/codec_client.cc:129] [Tags: "ConnectionId":"285"] response complete
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][pool] [source/common/conn_pool/conn_pool_base.cc:215] [Tags: "ConnectionId":"285"] destroying stream: 0 remaining
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http] [source/common/http/conn_manager_impl.cc:1855] [Tags: "ConnectionId":"275","StreamId":"11498334530499678467"] encoding trailers via codec:
envoy-5575cc449d-mkc8s envoy 'grpc-status', '0'
envoy-5575cc449d-mkc8s envoy 'grpc-message', ''
envoy-5575cc449d-mkc8s envoy 
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http] [source/common/http/conn_manager_impl.cc:1937] [Tags: "ConnectionId":"275","StreamId":"11498334530499678467"] Codec completed encoding stream.
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http2] [source/common/http/http2/codec_impl.cc:1445] [Tags: "ConnectionId":"275"] stream 1 closed: 0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http2] [source/common/http/http2/codec_impl.cc:1508] [Tags: "ConnectionId":"275"] Recouping 0 bytes of flow control window for stream 1.
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http2] [source/common/http/http2/codec_impl.cc:1930] [Tags: "ConnectionId":"275"] Http2Visitor invoking stream close listener for 1
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http2] [source/common/http/http2/codec_impl.cc:1908] [Tags: "ConnectionId":"285"] Http2Visitor::OnEndStream(3)
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http2] [source/common/http/http2/codec_impl.cc:1445] [Tags: "ConnectionId":"285"] stream 3 closed: 0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http2] [source/common/http/http2/codec_impl.cc:1508] [Tags: "ConnectionId":"285"] Recouping 0 bytes of flow control window for stream 3.
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.369][24][debug][http2] [source/common/http/http2/codec_impl.cc:1930] [Tags: "ConnectionId":"285"] Http2Visitor invoking stream close listener for 3
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.371][24][debug][connection] [source/common/network/connection_impl.cc:714] [Tags: "ConnectionId":"275"] remote close
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.371][24][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"275"] closing socket: 0
envoy-5575cc449d-mkc8s envoy [2024-10-20 16:37:21.371][24][debug][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"275"] adding to cleanup list

Some considerations

  • max_requests_per_connection: 1 always cause timeout because gRPC refection.
    • '/grpc.reflection.v1.ServerReflection/ServerReflectionInfo'
@toyamagu-2021 toyamagu-2021 added the triage Issue requires triage label Oct 20, 2024
@toyamagu-2021 toyamagu-2021 changed the title Envoy returns Message: stream timeout after idle_timeout when max_requests_per_connection set Envoy returns Message: stream timeout never handling pending gRPC requests when max_requests_per_connection is set Oct 20, 2024
@toyamagu-2021 toyamagu-2021 changed the title Envoy returns Message: stream timeout never handling pending gRPC requests when max_requests_per_connection is set Envoy returns Message: stream timeout without handling pending gRPC requests when max_requests_per_connection is set Oct 20, 2024
@mattklein123 mattklein123 added area/http and removed triage Issue requires triage labels Oct 21, 2024
@mattklein123
Copy link
Member

cc @alyssawilk for thoughts. I could see an argument for changing this behavior but it would not be easy and I'm not sure it justifies the regression risk.

@alyssawilk
Copy link
Contributor

I'd expect idle timeout if the timeout is reached when the session is queued waiting for an available upstream, or am I misunderstanding the concern?

@toyamagu-2021
Copy link
Author

toyamagu-2021 commented Oct 21, 2024 •
edited
Loading

idle timeout if the timeout is reached when the session is queued waiting for an available upstream

I agree with this, but I observe session is "queued" permanently even if prior session is finished.
Extremely, if we set timeout=0s and idle_timeout=0s, I thought all request should be handled, but didn't.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area/http
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@mattklein123 @alyssawilk @toyamagu-2021