search

envoyproxy / envoy

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

Listener filters w/ CONNECT can lead to traffic not being full sent to the upstream #36197

Open howardjohn opened 1 week ago

howardjohn commented 1 week ago

If you are reporting any crash or any potential security issue, do not open an issue in this repo. Please report the issue via emailing envoy-security@googlegroups.com where the issue will be triaged appropriately.

Title: Listener filters w/ CONNECT can lead to traffic not being full sent to the upstream

Description: We are experiencing an issue where requests are not making it to the upstream. The traffic here is a client that sends data then closes the connection; we see the data never makes it upstream.

Repro steps: We experience this in real world with Thrift apps and Istio. Below is a minimal pure envoy reproducer configuration.

config.yaml:

```yaml admin: access_log_path: /dev/stdout address: socket_address: protocol: TCP address: 127.0.0.1 port_value: 15000 bootstrapExtensions: - name: envoy.bootstrap.internal_listener typedConfig: '@type': type.googleapis.com/udpa.type.v1.TypedStruct typeUrl: type.googleapis.com/envoy.extensions.bootstrap.internal_listener.v3.InternalListener value: buffer_size_kb: 64 node: id: id cluster: test static_resources: listeners: - address: socket_address: address: 0.0.0.0 port_value: 10000 filter_chains: - filters: - name: envoy.filters.network.http_connection_manager typed_config: "@type": type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager stat_prefix: ingress_http route_config: name: local_route virtual_hosts: - name: local_service domains: - "*" routes: - match: connect_matcher: {} route: cluster: to-internal upgrade_configs: - upgrade_type: CONNECT connect_config: {} http_filters: - name: envoy.filters.http.router typed_config: "@type": type.googleapis.com/envoy.extensions.filters.http.router.v3.Router http2_protocol_options: allow_connect: true upgrade_configs: - upgrade_type: CONNECT - name: internal_listener internalListener: {} listenerFilters: # COMMENT ME OUT TO MAKE IT WORK - name: "envoy.filters.listener.tls_inspector" typed_config: "@type": type.googleapis.com/envoy.extensions.filters.listener.tls_inspector.v3.TlsInspector filter_chains: - filters: - name: envoy.filters.network.tcp_proxy typed_config: "@type": type.googleapis.com/envoy.extensions.filters.network.tcp_proxy.v3.TcpProxy cluster: to-connect_originate stat_prefix: to-connect_originate - name: connect_originate internalListener: {} filter_chains: - filters: - name: envoy.filters.network.tcp_proxy typed_config: "@type": type.googleapis.com/envoy.extensions.filters.network.tcp_proxy.v3.TcpProxy cluster: outbound stat_prefix: outbound clusters: - name: to-internal connect_timeout: 0.25s type: STATIC lb_policy: ROUND_ROBIN respect_dns_ttl: true load_assignment: cluster_name: to-internal endpoints: - lb_endpoints: - endpoint: address: envoyInternalAddress: serverListenerName: internal_listener endpointId: "10.244.0.91:7070" - name: to-connect_originate connect_timeout: 0.25s type: STATIC lb_policy: ROUND_ROBIN respect_dns_ttl: true load_assignment: cluster_name: to-connect_originate endpoints: - lb_endpoints: - endpoint: address: envoyInternalAddress: serverListenerName: connect_originate endpointId: "10.244.0.91:7070" - name: outbound connect_timeout: 0.25s type: LOGICAL_DNS lb_policy: ROUND_ROBIN respect_dns_ttl: true load_assignment: cluster_name: outbound endpoints: - lb_endpoints: - endpoint: address: socket_address: address: localhost port_value: 9090 ```

To run the full setup:

You should observe that you do NOT see a TCP Request log on the server.

Next, remove the listener_filter in the envoy config. Run the same test, you will see the TCP Request log.

Note: this is not an issue of the tls inspector not being able to parse the data. If the client app is changed to keep the connection alive, it is able to parse it (as non-tls). The same issue occurs with the http_inspector, fwiw.

Logs:

``` [2024-09-18 09:46:19.568][461551][trace][upstream] [external/envoy/source/extensions/clusters/logical_dns/logical_dns_cluster.cc:95] starting async DNS resolution for localhost [2024-09-18 09:46:19.568][461551][debug][dns] [external/envoy/source/extensions/network/dns_resolver/cares/dns_impl.cc:391] dns resolution for localhost started [2024-09-18 09:46:19.569][461551][debug][dns] [external/envoy/source/extensions/network/dns_resolver/cares/dns_impl.cc:308] dns resolution for localhost completed with status 0 [2024-09-18 09:46:19.569][461551][trace][upstream] [external/envoy/source/extensions/clusters/logical_dns/logical_dns_cluster.cc:103] async DNS resolution complete for localhost details cares_success:Successful completion [2024-09-18 09:46:19.569][461551][debug][upstream] [external/envoy/source/extensions/clusters/logical_dns/logical_dns_cluster.cc:157] DNS refresh rate reset for localhost, refresh rate 5000 ms [2024-09-18 09:46:19.569][461551][debug][main] [external/envoy/source/server/server.cc:237] flushing stats [2024-09-18 09:46:19.845][461564][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:136] LoadShedPoint envoy.load_shed_points.http_connection_manager_decode_headers is not found. Is it configured? [2024-09-18 09:46:19.845][461564][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:139] LoadShedPoint envoy.load_shed_points.hcm_ondata_creating_codec is not found. Is it configured? [2024-09-18 09:46:19.845][461564][trace][misc] [external/envoy/source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x48e3f75e780 for 3600000ms, min is 3600000ms [2024-09-18 09:46:19.845][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"0"] raising connection event 2 [2024-09-18 09:46:19.845][461564][debug][conn_handler] [external/envoy/source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"0"] new connection from 127.0.0.1:50274 [2024-09-18 09:46:19.845][461564][trace][misc] [external/envoy/source/common/network/tcp_listener_impl.cc:114] TcpListener accepted 1 new connections. [2024-09-18 09:46:19.845][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"0"] socket event: 3 [2024-09-18 09:46:19.845][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"0"] write ready [2024-09-18 09:46:19.845][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"0"] read ready. dispatch_buffered_data=0 [2024-09-18 09:46:19.845][461564][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"0"] read returns: 115 [2024-09-18 09:46:19.845][461564][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:39] [Tags: "ConnectionId":"0"] read error: Resource temporarily unavailable, code: 0 [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:2261] LoadShedPoint envoy.load_shed_points.http2_server_go_away_on_dispatch is not found. Is it configured? [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:2019] Codec does not have Metadata frame support. [2024-09-18 09:46:19.845][461564][debug][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1696] [Tags: "ConnectionId":"0"] updating connection-level initial window size to 268435456 [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1006] [Tags: "ConnectionId":"0"] dispatching 115 bytes [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"0"] Http2Visitor::OnFrameHeader(0, 18, 4, 0) [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1116] [Tags: "ConnectionId":"0"] about to recv frame type=4, flags=0, stream_id=0 [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1398] [Tags: "ConnectionId":"0"] track inbound frame type=4 flags=0 length=18 padding_length=0 [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"0"] Http2Visitor::OnFrameHeader(0, 4, 8, 0) [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1116] [Tags: "ConnectionId":"0"] about to recv frame type=8, flags=0, stream_id=0 [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1398] [Tags: "ConnectionId":"0"] track inbound frame type=8 flags=0 length=4 padding_length=0 [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"0"] Http2Visitor::OnFrameHeader(1, 42, 1, 4) [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1116] [Tags: "ConnectionId":"0"] about to recv frame type=1, flags=4, stream_id=1 [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1398] [Tags: "ConnectionId":"0"] track inbound frame type=1 flags=4 length=42 padding_length=0 [2024-09-18 09:46:19.845][461564][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:393] [Tags: "ConnectionId":"0"] new stream [2024-09-18 09:46:19.845][461564][trace][http] [external/envoy/source/common/http/filter_manager.h:1128] LoadShedPoint envoy.load_shed_points.http_downstream_filter_check is not found. Is it configured? [2024-09-18 09:46:19.845][461564][trace][misc] [external/envoy/source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x48e3f75e900 for 300000ms, min is 300000ms [2024-09-18 09:46:19.845][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1847] [Tags: "ConnectionId":"0"] Http2Visitor::OnEndHeadersForStream(1) [2024-09-18 09:46:19.845][461564][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1163] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] request headers complete (end_stream=false): ':authority', '127.0.0.1:10000' ':method', 'CONNECT' 'accept-encoding', 'gzip' 'user-agent', 'Go-http-client/2.0' [2024-09-18 09:46:19.845][461564][debug][connection] [external/envoy/source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"0"] current connecting state: false [2024-09-18 09:46:19.846][461564][debug][router] [external/envoy/source/common/router/router.cc:527] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] cluster 'to-internal' match for URL '' [2024-09-18 09:46:19.846][461564][debug][misc] [external/envoy/source/common/upstream/cluster_manager_impl.cc:2319] Allocating TCP conn pool [2024-09-18 09:46:19.846][461564][debug][router] [external/envoy/source/common/router/router.cc:756] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] router decoding headers: ':authority', '127.0.0.1:10000' ':method', 'CONNECT' ':scheme', 'http' 'accept-encoding', 'gzip' 'user-agent', 'Go-http-client/2.0' 'x-forwarded-proto', 'http' 'x-request-id', '0eb83527-b3ad-476c-acce-844c82bfc0dc' 'x-envoy-expected-rq-timeout-ms', '15000' [2024-09-18 09:46:19.846][461564][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:291] trying to create new connection [2024-09-18 09:46:19.846][461564][trace][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:292] ConnPoolImplBase 0x48e3fc31e00, ready_clients_.size(): 0, busy_clients_.size(): 0, connecting_clients_.size(): 0, connecting_stream_capacity_: 0, num_active_streams_: 0, pending_streams_.size(): 1 per upstream preconnect ratio: 1 [2024-09-18 09:46:19.846][461564][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:145] creating a new connection (connecting=0) [2024-09-18 09:46:19.846][461564][debug][connection] [external/envoy/source/extensions/bootstrap/internal_listener/client_connection_factory.cc:32] Internal client connection buffer size 65536. [2024-09-18 09:46:19.846][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/io_handle_impl.h:153] io handle 0x48e3fc83700 set peer handle to 0x48e3f7d6008. [2024-09-18 09:46:19.846][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/io_handle_impl.h:153] io handle 0x48e3f7d6000 set peer handle to 0x48e3fc83708. [2024-09-18 09:46:19.846][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/file_event_impl.cc:61] User space file event 0x48e3f79f240 set enabled events 3 and events 2 is active. Will reschedule. [2024-09-18 09:46:19.846][461564][trace][filter] [external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:106] tls inspector: new connection accepted [2024-09-18 09:46:19.846][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/file_event_impl.cc:61] User space file event 0x48e3f79e300 set enabled events 5 and events 0 is active. Will reschedule. [2024-09-18 09:46:19.846][461564][debug][connection] [external/envoy/source/common/network/connection_impl.cc:1017] [Tags: "ConnectionId":"1"] connecting to envoy://internal_listener/10.244.0.91:7070 [2024-09-18 09:46:19.846][461564][trace][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:131] not creating a new connection, shouldCreateNewConnection returned false. [2024-09-18 09:46:19.846][461564][trace][http] [external/envoy/source/common/http/filter_manager.cc:569] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] decode headers called: filter=envoy.filters.http.upstream_codec status=4 [2024-09-18 09:46:19.846][461564][trace][http] [external/envoy/source/common/http/filter_manager.cc:569] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] decode headers called: filter=envoy.filters.http.router status=1 [2024-09-18 09:46:19.846][461564][trace][misc] [external/envoy/source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x48e3f75e900 for 300000ms, min is 300000ms [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1044] [Tags: "ConnectionId":"0"] dispatched 115 bytes [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1371] [Tags: "ConnectionId":"0"] about to send frame type=4, flags=0 [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1420] [Tags: "ConnectionId":"0"] send data: bytes=33 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"0"] writing 33 bytes, end_stream false [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1264] [Tags: "ConnectionId":"0"] sent frame type=4, stream_id=0, length=24 [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1371] [Tags: "ConnectionId":"0"] about to send frame type=8, flags=0 [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1420] [Tags: "ConnectionId":"0"] send data: bytes=13 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"0"] writing 13 bytes, end_stream false [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1264] [Tags: "ConnectionId":"0"] sent frame type=8, stream_id=0, length=4 [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1371] [Tags: "ConnectionId":"0"] about to send frame type=4, flags=1 [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1420] [Tags: "ConnectionId":"0"] send data: bytes=9 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"0"] writing 9 bytes, end_stream false [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1264] [Tags: "ConnectionId":"0"] sent frame type=4, stream_id=0, length=0 [2024-09-18 09:46:19.846][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/file_event_impl.cc:16] User space event 0x48e3f79f240 invokes callbacks on events = 2 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"1"] socket event: 2 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"1"] write ready [2024-09-18 09:46:19.846][461564][debug][connection] [external/envoy/source/common/network/connection_impl.cc:746] [Tags: "ConnectionId":"1"] connected [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"1"] raising connection event 2 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:401] [Tags: "ConnectionId":"1"] readDisable: disable=true disable_count=0 state=0 buffer_length=0 [2024-09-18 09:46:19.846][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/file_event_impl.cc:61] User space file event 0x48e3f79f240 set enabled events 6 and events 2 is active. Will reschedule. [2024-09-18 09:46:19.846][461564][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:328] [Tags: "ConnectionId":"1"] attaching to next stream [2024-09-18 09:46:19.846][461564][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:182] [Tags: "ConnectionId":"1"] creating stream [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:401] [Tags: "ConnectionId":"1"] readDisable: disable=false disable_count=1 state=0 buffer_length=0 [2024-09-18 09:46:19.846][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/file_event_impl.cc:61] User space file event 0x48e3f79f240 set enabled events 3 and events 2 is active. Will not reschedule. [2024-09-18 09:46:19.846][461564][debug][router] [external/envoy/source/common/router/upstream_request.cc:593] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] pool ready [2024-09-18 09:46:19.846][461564][trace][router] [external/envoy/source/common/router/upstream_codec_filter.cc:61] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] proxying headers [2024-09-18 09:46:19.846][461564][trace][http] [external/envoy/source/common/http/filter_manager.cc:900] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false [2024-09-18 09:46:19.846][461564][trace][router] [external/envoy/source/common/router/upstream_request.cc:269] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] end_stream: false, upstream response headers: ':status', '200' [2024-09-18 09:46:19.846][461564][debug][router] [external/envoy/source/common/router/router.cc:1559] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] upstream headers complete: end_stream=false [2024-09-18 09:46:19.846][461564][trace][misc] [external/envoy/source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x48e3f75e900 for 300000ms, min is 300000ms [2024-09-18 09:46:19.846][461564][trace][http] [external/envoy/source/common/http/filter_manager.cc:900] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false [2024-09-18 09:46:19.846][461564][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1852] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] encoding headers via codec (end_stream=false): ':status', '200' 'date', 'Wed, 18 Sep 2024 16:46:19 GMT' 'server', 'envoy' [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1371] [Tags: "ConnectionId":"0"] about to send frame type=1, flags=4 [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1420] [Tags: "ConnectionId":"0"] send data: bytes=40 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"0"] writing 40 bytes, end_stream false [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1264] [Tags: "ConnectionId":"0"] sent frame type=1, stream_id=1, length=31 [2024-09-18 09:46:19.846][461564][trace][http] [external/envoy/source/common/http/filter_manager.cc:68] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] continuing filter chain: filter=0x48e3f75ea00 [2024-09-18 09:46:19.846][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/file_event_impl.cc:16] User space event 0x48e3f79e300 invokes callbacks on events = 1 [2024-09-18 09:46:19.846][461564][trace][filter] [external/envoy/source/common/network/listener_filter_buffer_impl.cc:95] onFileEvent: 1 [2024-09-18 09:46:19.846][461564][trace][filter] [external/envoy/source/common/network/listener_filter_buffer_impl.cc:60] recv returned: 0 [2024-09-18 09:46:19.846][461564][trace][filter] [external/envoy/source/common/network/listener_filter_buffer_impl.cc:64] recv return try again [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"0"] socket event: 2 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"0"] write ready [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:70] [Tags: "ConnectionId":"0"] write returns: 95 [2024-09-18 09:46:19.846][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/file_event_impl.cc:16] User space event 0x48e3f79f240 invokes callbacks on events = 2 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"1"] socket event: 2 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"1"] write ready [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"0"] socket event: 3 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"0"] write ready [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"0"] read ready. dispatch_buffered_data=0 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"0"] read returns: 9 [2024-09-18 09:46:19.846][461564][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:39] [Tags: "ConnectionId":"0"] read error: Resource temporarily unavailable, code: 0 [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1006] [Tags: "ConnectionId":"0"] dispatching 9 bytes [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1803] [Tags: "ConnectionId":"0"] Http2Visitor::OnFrameHeader(0, 0, 4, 1) [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1116] [Tags: "ConnectionId":"0"] about to recv frame type=4, flags=1, stream_id=0 [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1398] [Tags: "ConnectionId":"0"] track inbound frame type=4 flags=1 length=0 padding_length=0 [2024-09-18 09:46:19.846][461564][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1044] [Tags: "ConnectionId":"0"] dispatched 9 bytes [2024-09-18 09:46:19.848][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"0"] socket event: 3 [2024-09-18 09:46:19.848][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"0"] write ready [2024-09-18 09:46:19.848][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"0"] read ready. dispatch_buffered_data=0 [2024-09-18 09:46:19.848][461564][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"0"] read returns: 0 [2024-09-18 09:46:19.848][461564][debug][connection] [external/envoy/source/common/network/connection_impl.cc:714] [Tags: "ConnectionId":"0"] remote close [2024-09-18 09:46:19.848][461564][debug][connection] [external/envoy/source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"0"] closing socket: 0 [2024-09-18 09:46:19.848][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"0"] raising connection event 0 [2024-09-18 09:46:19.848][461564][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1921] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] stream reset: reset reason: connection termination, response details: - [2024-09-18 09:46:19.848][461564][debug][router] [external/envoy/source/common/router/upstream_request.cc:491] [Tags: "ConnectionId":"0","StreamId":"748492813854564191"] resetting pool request [2024-09-18 09:46:19.848][461564][debug][connection] [external/envoy/source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"1"] closing data_to_write=0 type=1 [2024-09-18 09:46:19.848][461564][debug][connection] [external/envoy/source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"1"] closing socket: 1 [2024-09-18 09:46:19.848][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/io_handle_impl.cc:73] socket 0x48e3fc83700 close before peer 0x48e3f7d6008 closes. [2024-09-18 09:46:19.848][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/io_handle_impl.h:116] setNewDataAvailable on socket 0x48e3f7d6000 [2024-09-18 09:46:19.848][461564][trace][connection] [external/envoy/source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"1"] raising connection event 1 [2024-09-18 09:46:19.848][461564][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:495] [Tags: "ConnectionId":"1"] client disconnected, failure reason: [2024-09-18 09:46:19.848][461564][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1) [2024-09-18 09:46:19.848][461564][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:463] invoking 1 idle callback(s) - is_draining_for_deletion_=false [2024-09-18 09:46:19.848][461564][trace][upstream] [external/envoy/source/common/upstream/cluster_manager_impl.cc:2198] Idle pool, erasing pool for host envoy://internal_listener/10.244.0.91:7070 [2024-09-18 09:46:19.848][461564][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2) [2024-09-18 09:46:19.848][461564][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:215] [Tags: "ConnectionId":"1"] destroying stream: 0 remaining [2024-09-18 09:46:19.848][461564][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:463] invoking 0 idle callback(s) - is_draining_for_deletion_=false [2024-09-18 09:46:19.848][461564][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=3) [2024-09-18 09:46:19.848][461564][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=4) [2024-09-18 09:46:19.848][461564][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=5) [2024-09-18 09:46:19.848][461564][trace][conn_handler] [external/envoy/source/common/listener_manager/active_stream_listener_base.cc:126] [Tags: "ConnectionId":"0"] tcp connection on event 0 [2024-09-18 09:46:19.848][461564][debug][conn_handler] [external/envoy/source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"0"] adding to cleanup list [2024-09-18 09:46:19.848][461564][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=6) [2024-09-18 09:46:19.848][461564][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=7) [2024-09-18 09:46:19.848][461564][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=7) [2024-09-18 09:46:19.848][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/file_event_impl.cc:16] User space event 0x48e3f79e300 invokes callbacks on events = 5 [2024-09-18 09:46:19.848][461564][trace][filter] [external/envoy/source/common/network/listener_filter_buffer_impl.cc:95] onFileEvent: 5 [2024-09-18 09:46:19.848][461564][trace][io] [external/envoy/source/extensions/io_socket/user_space/io_handle_impl.cc:80] socket 0x48e3f7d6000 close after peer closed. [2024-09-18 09:46:19.848][461564][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1) [2024-09-18 09:46:19.848][461564][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=1) ```
zuercher commented 1 week ago

cc @alyssawilk