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

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

Open
howardjohn opened this issue Sep 18, 2024 · 1 comment
Open

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

howardjohn opened this issue Sep 18, 2024 · 1 comment
Labels
area/listener bug triage Issue requires triage

Comments

@howardjohn
Copy link
Contributor

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:

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:

  • envoy -c config.yaml
  • Clone https://github.com/howardjohn/istio/tree/exp/echo-oneshot.
    • go run ./pkg/test/echo/cmd/server to run the test server
    • go run ./pkg/test/echo/cmd/client --hbone 127.0.0.1:10000 tcp://127.0.0.1:10000 to run the test client. This will establish a CONNECT call, send some data over it, then close the connection.

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)
@howardjohn howardjohn added bug triage Issue requires triage labels Sep 18, 2024
@zuercher
Copy link
Member

cc @alyssawilk

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

No branches or pull requests
2 participants
@zuercher @howardjohn