search

envoyproxy / envoy

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

XFF Header Processing Change Breaks Client IP Detection When Using CustomHeaderConfig in Original IP Detection #37171

Open agrawroh opened 2 days ago

agrawroh commented 2 days ago

Title: XFF Header Processing Change Breaks Client IP Detection When Using CustomHeaderConfig in Original IP Detection

Description

After implementing support for configuring trusted CIDRs in XFF original IP detection (#31831), Envoy is incorrectly appending the IPs in XFF which is causing issues while determining the original client IP.

The change was intended to add support for evaluating client IP addresses against a list of trusted CIDRs, similar to Nginx's realip module functionality. However, this has resulted in unexpected behavior where an additional value is being appended to the XFF header when forwarding requests to upstream services.

We are suspecting it's because of returning false for skip_xff_append here which gets evaluated in HCM here.

With the new version (v1.32.x), we see:

':authority', 'localhost'
':path', '/foo'
':method', 'GET'
'user-agent', 'curl/7.68.0'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', '9b392a21-0499-440b-b7db-0d7dc401dd1d'
'x-real-ip', '1.2.3.4'
'x-forwarded-for', '1.2.3.4,10.110.156.62'     <---------- SEE THIS
'x-envoy-expected-rq-timeout-ms', '120000'

With the old version (v1.30.x), we see:

':authority', 'localhost'
':path', '/foo'
':method', 'GET'
'user-agent', 'curl/8.7.1'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', 'c976b755-2903-40ab-ac4d-3cd000c9f229'
'x-real-ip', '1.2.3.4'
'x-forwarded-for', '1.2.3.4'     <---------- SEE THIS
'x-envoy-expected-rq-timeout-ms', '120000'

Repro Steps

Configuration

# Make requests using the following command(s):
# curl -vvv http://localhost:80/foo
static_resources:
  clusters:
    - name: my_cluster_2
      connect_timeout: 5.0s
      type: strict_dns
      lb_policy: round_robin
      load_assignment:
        cluster_name: my_cluster_2
        endpoints:
          lb_endpoints:
            - endpoint:
                address:
                  socket_address:
                    address: 0.0.0.0
                    port_value: 8443
    - name: my_cluster_3
      connect_timeout: 5.0s
      type: strict_dns
      lb_policy: round_robin
      load_assignment:
        cluster_name: my_cluster_3
        endpoints:
          lb_endpoints:
            - endpoint:
                address:
                  socket_address:
                    address: 0.0.0.0
                    port_value: 8444
  listeners:
    - name: my_listener_1
      address:
        socket_address:
          protocol: TCP
          address: 0.0.0.0
          port_value: 80
      listener_filters:
        - name: envoy.filters.listener.tls_inspector
          typed_config:
            "@type": type.googleapis.com/envoy.extensions.filters.listener.tls_inspector.v3.TlsInspector
      filter_chains:
        - name: allow-traffic
          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: my_listener_1_http
                use_remote_address: false
                route_config:
                  name: main_routes
                  virtual_hosts:
                    - name: main_vh
                      domains:
                        - "*"
                      routes:
                        - match:
                            prefix: /
                          route:
                            cluster: my_cluster_2
                            timeout: 120s
                          request_headers_to_add:
                            - header:
                                key: x-real-ip
                                value: 1.2.3.4
                            - header:
                                key: x-forwarded-for
                                value: 1.2.3.4
                http_filters:
                  - name: envoy.filters.http.router
                    typed_config:
                      "@type": type.googleapis.com/envoy.extensions.filters.http.router.v3.Router
    - name: my_listener_2
      address:
        socket_address:
          protocol: TCP
          address: 0.0.0.0
          port_value: 8443
      listener_filters:
        - name: envoy.filters.listener.tls_inspector
          typed_config:
            "@type": type.googleapis.com/envoy.extensions.filters.listener.tls_inspector.v3.TlsInspector
      filter_chains:
        - name: allow-traffic
          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: my_listener_2_http
                use_remote_address: false
                xff_num_trusted_hops: 0
                original_ip_detection_extensions:
                  - name: envoy.http.original_ip_detection.custom_header
                    typed_config:
                      "@type": type.googleapis.com/envoy.extensions.http.original_ip_detection.custom_header.v3.CustomHeaderConfig
                      header_name: x-real-ip
                      allow_extension_to_set_address_as_trusted: true
                      reject_with_status:
                        code: Forbidden
                route_config:
                  name: main_routes
                  virtual_hosts:
                    - name: main_vh
                      domains:
                        - "*"
                      routes:
                        - match:
                            prefix: /
                          route:
                            cluster: my_cluster_3
                            timeout: 120s
                http_filters:
                  - name: envoy.filters.http.router
                    typed_config:
                      "@type": type.googleapis.com/envoy.extensions.filters.http.router.v3.Router
    - name: my_listener_3
      address:
        socket_address:
          protocol: TCP
          address: 0.0.0.0
          port_value: 8444
      listener_filters:
        - name: envoy.filters.listener.tls_inspector
          typed_config:
            "@type": type.googleapis.com/envoy.extensions.filters.listener.tls_inspector.v3.TlsInspector
      filter_chains:
        - name: allow-traffic
          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: my_listener_3_http
                route_config:
                  name: main_routes
                  virtual_hosts:
                    - name: main_vh
                      domains:
                        - "*"
                      routes:
                        - match:
                            prefix: /
                          direct_response:
                            body:
                              inline_string: OK
                            status: 200
                http_filters:
                  - name: envoy.filters.http.router
                    typed_config:
                      "@type": type.googleapis.com/envoy.extensions.filters.http.router.v3.Router

Request

Send a cURL request with v1.30 and v1.32 like this:

curl -vvv http://localhost:80/foo

Output

v1.32

[2024-11-15 09:32:29.141][12033][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:410] dns resolution for 0.0.0.0 started
[2024-11-15 09:32:29.141][12033][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:327] dns resolution for 0.0.0.0 completed with status 0
[2024-11-15 09:32:29.142][12033][debug][upstream] [source/common/upstream/upstream_impl.cc:485] transport socket match, socket default selected for host with address 0.0.0.0:8443
[2024-11-15 09:32:29.142][12033][debug][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:211] DNS refresh rate reset for 0.0.0.0, refresh rate 5000 ms
[2024-11-15 09:32:29.142][12033][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:410] dns resolution for 0.0.0.0 started
[2024-11-15 09:32:29.142][12033][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:327] dns resolution for 0.0.0.0 completed with status 0
[2024-11-15 09:32:29.142][12033][debug][upstream] [source/common/upstream/upstream_impl.cc:485] transport socket match, socket default selected for host with address 0.0.0.0:8444
[2024-11-15 09:32:29.142][12033][debug][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:211] DNS refresh rate reset for 0.0.0.0, refresh rate 5000 ms
[2024-11-15 09:32:29.201][12033][debug][main] [source/server/server.cc:238] flushing stats
[2024-11-15 09:32:30.347][12097][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"0"] new connection from 127.0.0.1:53166
[2024-11-15 09:32:30.348][12097][debug][http] [source/common/http/conn_manager_impl.cc:394] [Tags: "ConnectionId":"0"] new stream
[2024-11-15 09:32:30.348][12097][debug][http] [source/common/http/conn_manager_impl.cc:1184] [Tags: "ConnectionId":"0","StreamId":"10315118978607584203"] request headers complete (end_stream=true):
':authority', 'localhost'
':path', '/foo'
':method', 'GET'
'user-agent', 'curl/7.68.0'
'accept', '*/*'

[2024-11-15 09:32:30.348][12097][debug][http] [source/common/http/conn_manager_impl.cc:1167] [Tags: "ConnectionId":"0","StreamId":"10315118978607584203"] request end stream timestamp recorded
[2024-11-15 09:32:30.348][12097][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"0"] current connecting state: false
[2024-11-15 09:32:30.349][12097][debug][router] [source/common/router/router.cc:527] [Tags: "ConnectionId":"0","StreamId":"10315118978607584203"] cluster 'my_cluster_2' match for URL '/foo'
[2024-11-15 09:32:30.349][12097][debug][router] [source/common/router/router.cc:756] [Tags: "ConnectionId":"0","StreamId":"10315118978607584203"] router decoding headers:
':authority', 'localhost'
':path', '/foo'
':method', 'GET'
':scheme', 'http'
'user-agent', 'curl/7.68.0'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', '9b392a21-0499-440b-b7db-0d7dc401dd1d'
'x-envoy-expected-rq-timeout-ms', '120000'
'x-real-ip', '1.2.3.4'
'x-forwarded-for', '1.2.3.4'

[2024-11-15 09:32:30.349][12097][debug][pool] [source/common/http/conn_pool_base.cc:78] queueing stream due to no available connections (ready=0 busy=0 connecting=0)
[2024-11-15 09:32:30.349][12097][debug][pool] [source/common/conn_pool/conn_pool_base.cc:291] trying to create new connection
[2024-11-15 09:32:30.349][12097][debug][pool] [source/common/conn_pool/conn_pool_base.cc:145] creating a new connection (connecting=0)
[2024-11-15 09:32:30.350][12097][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"1"] current connecting state: true
[2024-11-15 09:32:30.350][12097][debug][client] [source/common/http/codec_client.cc:57] [Tags: "ConnectionId":"1"] connecting
[2024-11-15 09:32:30.350][12097][debug][connection] [source/common/network/connection_impl.cc:1017] [Tags: "ConnectionId":"1"] connecting to 0.0.0.0:8443
[2024-11-15 09:32:30.350][12097][debug][connection] [source/common/network/connection_impl.cc:1036] [Tags: "ConnectionId":"1"] connection in progress
[2024-11-15 09:32:30.350][12097][debug][connection] [source/common/network/connection_impl.cc:746] [Tags: "ConnectionId":"1"] connected
[2024-11-15 09:32:30.350][12097][debug][client] [source/common/http/codec_client.cc:88] [Tags: "ConnectionId":"1"] connected
[2024-11-15 09:32:30.350][12097][debug][pool] [source/common/conn_pool/conn_pool_base.cc:328] [Tags: "ConnectionId":"1"] attaching to next stream
[2024-11-15 09:32:30.350][12097][debug][pool] [source/common/conn_pool/conn_pool_base.cc:182] [Tags: "ConnectionId":"1"] creating stream
[2024-11-15 09:32:30.350][12097][debug][router] [source/common/router/upstream_request.cc:589] [Tags: "ConnectionId":"0","StreamId":"10315118978607584203"] pool ready
[2024-11-15 09:32:30.350][12097][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"1"] encode complete
[2024-11-15 09:32:30.350][12074][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"2"] new connection from 127.0.0.1:38274
[2024-11-15 09:32:30.351][12074][debug][http] [source/common/http/conn_manager_impl.cc:394] [Tags: "ConnectionId":"2"] new stream
[2024-11-15 09:32:30.351][12074][debug][http] [source/common/http/conn_manager_impl.cc:1184] [Tags: "ConnectionId":"2","StreamId":"16676946837840269223"] request headers complete (end_stream=true):
':authority', 'localhost'
':path', '/foo'
':method', 'GET'
'user-agent', 'curl/7.68.0'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', '9b392a21-0499-440b-b7db-0d7dc401dd1d'
'x-envoy-expected-rq-timeout-ms', '120000'
'x-real-ip', '1.2.3.4'
'x-forwarded-for', '1.2.3.4'

[2024-11-15 09:32:30.351][12074][debug][http] [source/common/http/conn_manager_impl.cc:1167] [Tags: "ConnectionId":"2","StreamId":"16676946837840269223"] request end stream timestamp recorded
[2024-11-15 09:32:30.351][12074][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"2"] current connecting state: false
[2024-11-15 09:32:30.351][12074][debug][router] [source/common/router/router.cc:527] [Tags: "ConnectionId":"2","StreamId":"16676946837840269223"] cluster 'my_cluster_3' match for URL '/foo'
[2024-11-15 09:32:30.351][12074][debug][router] [source/common/router/router.cc:756] [Tags: "ConnectionId":"2","StreamId":"16676946837840269223"] router decoding headers:
':authority', 'localhost'
':path', '/foo'
':method', 'GET'
':scheme', 'http'
'user-agent', 'curl/7.68.0'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', '9b392a21-0499-440b-b7db-0d7dc401dd1d'
'x-real-ip', '1.2.3.4'
'x-forwarded-for', '1.2.3.4,10.110.156.62'
'x-envoy-expected-rq-timeout-ms', '120000'

[2024-11-15 09:32:30.352][12074][debug][pool] [source/common/http/conn_pool_base.cc:78] queueing stream due to no available connections (ready=0 busy=0 connecting=0)
[2024-11-15 09:32:30.352][12074][debug][pool] [source/common/conn_pool/conn_pool_base.cc:291] trying to create new connection
[2024-11-15 09:32:30.352][12074][debug][pool] [source/common/conn_pool/conn_pool_base.cc:145] creating a new connection (connecting=0)
[2024-11-15 09:32:30.352][12074][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"3"] current connecting state: true
[2024-11-15 09:32:30.352][12074][debug][client] [source/common/http/codec_client.cc:57] [Tags: "ConnectionId":"3"] connecting
[2024-11-15 09:32:30.352][12074][debug][connection] [source/common/network/connection_impl.cc:1017] [Tags: "ConnectionId":"3"] connecting to 0.0.0.0:8444
[2024-11-15 09:32:30.352][12074][debug][connection] [source/common/network/connection_impl.cc:1036] [Tags: "ConnectionId":"3"] connection in progress
[2024-11-15 09:32:30.352][12074][debug][connection] [source/common/network/connection_impl.cc:746] [Tags: "ConnectionId":"3"] connected
[2024-11-15 09:32:30.352][12074][debug][client] [source/common/http/codec_client.cc:88] [Tags: "ConnectionId":"3"] connected
[2024-11-15 09:32:30.353][12074][debug][pool] [source/common/conn_pool/conn_pool_base.cc:328] [Tags: "ConnectionId":"3"] attaching to next stream
[2024-11-15 09:32:30.353][12074][debug][pool] [source/common/conn_pool/conn_pool_base.cc:182] [Tags: "ConnectionId":"3"] creating stream
[2024-11-15 09:32:30.353][12074][debug][router] [source/common/router/upstream_request.cc:589] [Tags: "ConnectionId":"2","StreamId":"16676946837840269223"] pool ready
[2024-11-15 09:32:30.353][12074][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"3"] encode complete
[2024-11-15 09:32:30.353][12098][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"4"] new connection from 127.0.0.1:60364
[2024-11-15 09:32:30.353][12098][debug][http] [source/common/http/conn_manager_impl.cc:394] [Tags: "ConnectionId":"4"] new stream
[2024-11-15 09:32:30.354][12098][debug][http] [source/common/http/conn_manager_impl.cc:1184] [Tags: "ConnectionId":"4","StreamId":"12614797142382797470"] request headers complete (end_stream=true):
':authority', 'localhost'
':path', '/foo'
':method', 'GET'
'user-agent', 'curl/7.68.0'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', '9b392a21-0499-440b-b7db-0d7dc401dd1d'
'x-real-ip', '1.2.3.4'
'x-forwarded-for', '1.2.3.4,10.110.156.62'
'x-envoy-expected-rq-timeout-ms', '120000'

[2024-11-15 09:32:30.354][12098][debug][http] [source/common/http/conn_manager_impl.cc:1167] [Tags: "ConnectionId":"4","StreamId":"12614797142382797470"] request end stream timestamp recorded
[2024-11-15 09:32:30.354][12098][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"4"] current connecting state: false
[2024-11-15 09:32:30.354][12098][debug][http] [source/common/http/filter_manager.cc:1034] [Tags: "ConnectionId":"4","StreamId":"12614797142382797470"] Preparing local reply with details direct_response
[2024-11-15 09:32:30.354][12098][debug][http] [source/common/http/filter_manager.cc:1076] [Tags: "ConnectionId":"4","StreamId":"12614797142382797470"] Executing sending local reply.
[2024-11-15 09:32:30.354][12098][debug][http] [source/common/http/conn_manager_impl.cc:1879] [Tags: "ConnectionId":"4","StreamId":"12614797142382797470"] encoding headers via codec (end_stream=false):
':status', '200'
'content-length', '2'
'content-type', 'text/plain'
'date', 'Fri, 15 Nov 2024 09:32:30 GMT'
'server', 'envoy'

[2024-11-15 09:32:30.354][12098][debug][http] [source/common/http/conn_manager_impl.cc:1994] [Tags: "ConnectionId":"4","StreamId":"12614797142382797470"] Codec completed encoding stream.
[2024-11-15 09:32:30.354][12074][debug][router] [source/common/router/router.cc:1554] [Tags: "ConnectionId":"2","StreamId":"16676946837840269223"] upstream headers complete: end_stream=false
[2024-11-15 09:32:30.355][12074][debug][http] [source/common/http/conn_manager_impl.cc:1879] [Tags: "ConnectionId":"2","StreamId":"16676946837840269223"] encoding headers via codec (end_stream=false):
':status', '200'
'content-length', '2'
'content-type', 'text/plain'
'date', 'Fri, 15 Nov 2024 09:32:30 GMT'
'server', 'envoy'
'x-envoy-upstream-service-time', '1'

[2024-11-15 09:32:30.355][12074][debug][client] [source/common/http/codec_client.cc:129] [Tags: "ConnectionId":"3"] response complete
[2024-11-15 09:32:30.356][12074][debug][http] [source/common/http/conn_manager_impl.cc:1994] [Tags: "ConnectionId":"2","StreamId":"16676946837840269223"] Codec completed encoding stream.
[2024-11-15 09:32:30.356][12074][debug][pool] [source/common/http/http1/conn_pool.cc:53] [Tags: "ConnectionId":"3"] response complete
[2024-11-15 09:32:30.356][12074][debug][pool] [source/common/conn_pool/conn_pool_base.cc:215] [Tags: "ConnectionId":"3"] destroying stream: 0 remaining
[2024-11-15 09:32:30.356][12097][debug][router] [source/common/router/router.cc:1554] [Tags: "ConnectionId":"0","StreamId":"10315118978607584203"] upstream headers complete: end_stream=false
[2024-11-15 09:32:30.357][12097][debug][http] [source/common/http/conn_manager_impl.cc:1879] [Tags: "ConnectionId":"0","StreamId":"10315118978607584203"] encoding headers via codec (end_stream=false):
':status', '200'
'content-length', '2'
'content-type', 'text/plain'
'date', 'Fri, 15 Nov 2024 09:32:30 GMT'
'server', 'envoy'
'x-envoy-upstream-service-time', '6'

[2024-11-15 09:32:30.357][12097][debug][client] [source/common/http/codec_client.cc:129] [Tags: "ConnectionId":"1"] response complete

v1.30

[2024-11-15 15:01:05.523][31760463][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"0"] new connection from 127.0.0.1:49429
[2024-11-15 15:01:05.523][31760463][debug][http] [source/common/http/conn_manager_impl.cc:385] [Tags: "ConnectionId":"0"] new stream
[2024-11-15 15:01:05.523][31760463][debug][http] [source/common/http/conn_manager_impl.cc:1135] [Tags: "ConnectionId":"0","StreamId":"7639773342097111712"] request headers complete (end_stream=true):
':authority', 'localhost'
':path', '/foo'
':method', 'GET'
'user-agent', 'curl/8.7.1'
'accept', '*/*'

[2024-11-15 15:01:05.523][31760463][debug][http] [source/common/http/conn_manager_impl.cc:1118] [Tags: "ConnectionId":"0","StreamId":"7639773342097111712"] request end stream
[2024-11-15 15:01:05.523][31760463][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"0"] current connecting state: false
[2024-11-15 15:01:05.523][31760463][debug][router] [source/common/router/router.cc:525] [Tags: "ConnectionId":"0","StreamId":"7639773342097111712"] cluster 'my_cluster_2' match for URL '/foo'
[2024-11-15 15:01:05.523][31760463][debug][router] [source/common/router/router.cc:750] [Tags: "ConnectionId":"0","StreamId":"7639773342097111712"] router decoding headers:
':authority', 'localhost'
':path', '/foo'
':method', 'GET'
':scheme', 'http'
'user-agent', 'curl/8.7.1'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', 'c976b755-2903-40ab-ac4d-3cd000c9f229'
'x-envoy-expected-rq-timeout-ms', '120000'
'x-real-ip', '1.2.3.4'
'x-forwarded-for', '1.2.3.4'

[2024-11-15 15:01:05.523][31760463][debug][pool] [source/common/http/conn_pool_base.cc:78] queueing stream due to no available connections (ready=0 busy=0 connecting=0)
[2024-11-15 15:01:05.523][31760463][debug][pool] [source/common/conn_pool/conn_pool_base.cc:291] trying to create new connection
[2024-11-15 15:01:05.523][31760463][debug][pool] [source/common/conn_pool/conn_pool_base.cc:145] creating a new connection (connecting=0)
[2024-11-15 15:01:05.523][31760463][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"1"] current connecting state: true
[2024-11-15 15:01:05.523][31760463][debug][client] [source/common/http/codec_client.cc:57] [Tags: "ConnectionId":"1"] connecting
[2024-11-15 15:01:05.523][31760463][debug][connection] [source/common/network/connection_impl.cc:1017] [Tags: "ConnectionId":"1"] connecting to 0.0.0.0:8443
[2024-11-15 15:01:05.523][31760463][debug][connection] [source/common/network/connection_impl.cc:1036] [Tags: "ConnectionId":"1"] connection in progress
[2024-11-15 15:01:05.524][31760463][debug][connection] [source/common/network/connection_impl.cc:746] [Tags: "ConnectionId":"1"] connected
[2024-11-15 15:01:05.524][31760463][debug][client] [source/common/http/codec_client.cc:88] [Tags: "ConnectionId":"1"] connected
[2024-11-15 15:01:05.524][31760463][debug][pool] [source/common/conn_pool/conn_pool_base.cc:328] [Tags: "ConnectionId":"1"] attaching to next stream
[2024-11-15 15:01:05.524][31760463][debug][pool] [source/common/conn_pool/conn_pool_base.cc:182] [Tags: "ConnectionId":"1"] creating stream
[2024-11-15 15:01:05.524][31760463][debug][router] [source/common/router/upstream_request.cc:595] [Tags: "ConnectionId":"0","StreamId":"7639773342097111712"] pool ready
[2024-11-15 15:01:05.524][31760463][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"1"] encode complete
[2024-11-15 15:01:05.524][31760472][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"2"] new connection from 127.0.0.1:49430
[2024-11-15 15:01:05.524][31760472][debug][http] [source/common/http/conn_manager_impl.cc:385] [Tags: "ConnectionId":"2"] new stream
[2024-11-15 15:01:05.524][31760472][debug][http] [source/common/http/conn_manager_impl.cc:1135] [Tags: "ConnectionId":"2","StreamId":"11705774902034065365"] request headers complete (end_stream=true):
':authority', 'localhost'
':path', '/foo'
':method', 'GET'
'user-agent', 'curl/8.7.1'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', 'c976b755-2903-40ab-ac4d-3cd000c9f229'
'x-envoy-expected-rq-timeout-ms', '120000'
'x-real-ip', '1.2.3.4'
'x-forwarded-for', '1.2.3.4'

[2024-11-15 15:01:05.524][31760472][debug][http] [source/common/http/conn_manager_impl.cc:1118] [Tags: "ConnectionId":"2","StreamId":"11705774902034065365"] request end stream
[2024-11-15 15:01:05.524][31760472][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"2"] current connecting state: false
[2024-11-15 15:01:05.524][31760472][debug][router] [source/common/router/router.cc:525] [Tags: "ConnectionId":"2","StreamId":"11705774902034065365"] cluster 'my_cluster_3' match for URL '/foo'
[2024-11-15 15:01:05.524][31760472][debug][router] [source/common/router/router.cc:750] [Tags: "ConnectionId":"2","StreamId":"11705774902034065365"] router decoding headers:
':authority', 'localhost'
':path', '/foo'
':method', 'GET'
':scheme', 'http'
'user-agent', 'curl/8.7.1'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', 'c976b755-2903-40ab-ac4d-3cd000c9f229'
'x-real-ip', '1.2.3.4'
'x-forwarded-for', '1.2.3.4'
'x-envoy-expected-rq-timeout-ms', '120000'

[2024-11-15 15:01:05.524][31760472][debug][pool] [source/common/http/conn_pool_base.cc:78] queueing stream due to no available connections (ready=0 busy=0 connecting=0)
[2024-11-15 15:01:05.524][31760472][debug][pool] [source/common/conn_pool/conn_pool_base.cc:291] trying to create new connection
[2024-11-15 15:01:05.524][31760472][debug][pool] [source/common/conn_pool/conn_pool_base.cc:145] creating a new connection (connecting=0)
[2024-11-15 15:01:05.525][31760472][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"3"] current connecting state: true
[2024-11-15 15:01:05.525][31760472][debug][client] [source/common/http/codec_client.cc:57] [Tags: "ConnectionId":"3"] connecting
[2024-11-15 15:01:05.525][31760472][debug][connection] [source/common/network/connection_impl.cc:1017] [Tags: "ConnectionId":"3"] connecting to 0.0.0.0:8444
[2024-11-15 15:01:05.525][31760472][debug][connection] [source/common/network/connection_impl.cc:1036] [Tags: "ConnectionId":"3"] connection in progress
[2024-11-15 15:01:05.525][31760472][debug][connection] [source/common/network/connection_impl.cc:746] [Tags: "ConnectionId":"3"] connected
[2024-11-15 15:01:05.525][31760472][debug][client] [source/common/http/codec_client.cc:88] [Tags: "ConnectionId":"3"] connected
[2024-11-15 15:01:05.525][31760472][debug][pool] [source/common/conn_pool/conn_pool_base.cc:328] [Tags: "ConnectionId":"3"] attaching to next stream
[2024-11-15 15:01:05.525][31760472][debug][pool] [source/common/conn_pool/conn_pool_base.cc:182] [Tags: "ConnectionId":"3"] creating stream
[2024-11-15 15:01:05.525][31760472][debug][router] [source/common/router/upstream_request.cc:595] [Tags: "ConnectionId":"2","StreamId":"11705774902034065365"] pool ready
[2024-11-15 15:01:05.525][31760472][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"3"] encode complete
[2024-11-15 15:01:05.525][31760464][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"4"] new connection from 127.0.0.1:49431
[2024-11-15 15:01:05.525][31760464][debug][http] [source/common/http/conn_manager_impl.cc:385] [Tags: "ConnectionId":"4"] new stream
[2024-11-15 15:01:05.525][31760464][debug][http] [source/common/http/conn_manager_impl.cc:1135] [Tags: "ConnectionId":"4","StreamId":"6422728508326757723"] request headers complete (end_stream=true):
':authority', 'localhost'
':path', '/foo'
':method', 'GET'
'user-agent', 'curl/8.7.1'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', 'c976b755-2903-40ab-ac4d-3cd000c9f229'
'x-real-ip', '1.2.3.4'
'x-forwarded-for', '1.2.3.4'
'x-envoy-expected-rq-timeout-ms', '120000'

[2024-11-15 15:01:05.525][31760464][debug][http] [source/common/http/conn_manager_impl.cc:1118] [Tags: "ConnectionId":"4","StreamId":"6422728508326757723"] request end stream
[2024-11-15 15:01:05.525][31760464][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"4"] current connecting state: false
[2024-11-15 15:01:05.525][31760464][debug][http] [source/common/http/filter_manager.cc:1025] [Tags: "ConnectionId":"4","StreamId":"6422728508326757723"] Preparing local reply with details direct_response
[2024-11-15 15:01:05.525][31760464][debug][http] [source/common/http/filter_manager.cc:1067] [Tags: "ConnectionId":"4","StreamId":"6422728508326757723"] Executing sending local reply.
[2024-11-15 15:01:05.525][31760464][debug][http] [source/common/http/conn_manager_impl.cc:1825] [Tags: "ConnectionId":"4","StreamId":"6422728508326757723"] encoding headers via codec (end_stream=false):
':status', '200'
'content-length', '2'
'content-type', 'text/plain'
'date', 'Fri, 15 Nov 2024 09:31:05 GMT'
'server', 'envoy'

[2024-11-15 15:01:05.525][31760464][debug][http] [source/common/http/conn_manager_impl.cc:1937] [Tags: "ConnectionId":"4","StreamId":"6422728508326757723"] Codec completed encoding stream.
[2024-11-15 15:01:05.526][31760472][debug][router] [source/common/router/router.cc:1551] [Tags: "ConnectionId":"2","StreamId":"11705774902034065365"] upstream headers complete: end_stream=false
[2024-11-15 15:01:05.526][31760472][debug][http] [source/common/http/conn_manager_impl.cc:1825] [Tags: "ConnectionId":"2","StreamId":"11705774902034065365"] encoding headers via codec (end_stream=false):
':status', '200'
'content-length', '2'
'content-type', 'text/plain'
'date', 'Fri, 15 Nov 2024 09:31:05 GMT'
'server', 'envoy'
'x-envoy-upstream-service-time', '0'

[2024-11-15 15:01:05.526][31760472][debug][client] [source/common/http/codec_client.cc:129] [Tags: "ConnectionId":"3"] response complete
[2024-11-15 15:01:05.526][31760472][debug][http] [source/common/http/conn_manager_impl.cc:1937] [Tags: "ConnectionId":"2","StreamId":"11705774902034065365"] Codec completed encoding stream.
[2024-11-15 15:01:05.526][31760472][debug][pool] [source/common/http/http1/conn_pool.cc:53] [Tags: "ConnectionId":"3"] response complete
[2024-11-15 15:01:05.526][31760472][debug][pool] [source/common/conn_pool/conn_pool_base.cc:215] [Tags: "ConnectionId":"3"] destroying stream: 0 remaining
[2024-11-15 15:01:05.526][31760463][debug][router] [source/common/router/router.cc:1551] [Tags: "ConnectionId":"0","StreamId":"7639773342097111712"] upstream headers complete: end_stream=false
[2024-11-15 15:01:05.526][31760463][debug][http] [source/common/http/conn_manager_impl.cc:1825] [Tags: "ConnectionId":"0","StreamId":"7639773342097111712"] encoding headers via codec (end_stream=false):
':status', '200'
'content-length', '2'
'content-type', 'text/plain'
'date', 'Fri, 15 Nov 2024 09:31:05 GMT'
'server', 'envoy'
'x-envoy-upstream-service-time', '2'

[2024-11-15 15:01:05.526][31760463][debug][client] [source/common/http/codec_client.cc:129] [Tags: "ConnectionId":"1"] response complete
wbpcode commented 8 hours ago

yeah, I think this is an expected change and should be fixed as a bug. We never expect the custom header to append xff.