search

envoyproxy / envoy

Cloud-native high-performance edge/middle/service proxy
https://www.envoyproxy.io
Apache License 2.0
25.1k stars 4.82k forks source link

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

Open toyamagu-2021 opened 1 month ago

toyamagu-2021 commented 1 month ago

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 ```yaml 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 ```log 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 ```log 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

mattklein123 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 left "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.

github-actions[bot] commented 4 days ago

This issue has been automatically marked as stale because it has not had activity in the last 30 days. It will be closed in the next 7 days unless it is tagged "help wanted" or "no stalebot" or other activity occurs. Thank you for your contributions.