envoy doesn't send vhds request to xds

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: envoy doesn't send vhds request to xds

Description:

we configured vhds with ads as config_source, but when we tried it out, our request just timed out and we didn't find any vhds request in the log. Our xds server didn't receive any vhds request.

Repro steps:

Include sample requests, environment, etc. All data and inputs required to reproduce the bug.

Note: The Envoy_collect tool gathers a tarball with debug logs, config and the following admin endpoints: /stats, /clusters and /server_info. Please note if there are privacy concerns, sanitize the data prior to sharing the tarball/pasting.

Admin and Stats Output:

Include the admin output for the following endpoints: /stats, /clusters, /routes, /server_info. For more information, refer to the admin endpoint documentation.

Note: If there are privacy concerns, sanitize the data prior to sharing.

Config:

Include the config used to configure Envoy.

node:
  cluster: test-cluster
  id: envoy-helloworld-frontend
  listening_addresses:
    - socket_address:
        protocol: TCP
        address: envoy-helloworld-frontend
        port_value: 10000

dynamic_resources:
  ads_config:
    api_type: DELTA_GRPC
    transport_api_version: V3
    grpc_services:
      - envoy_grpc:
          cluster_name: xds_cluster

           - 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: outbound_route
                  vhds:
                    config_source:
                      ads: {}
                http_filters:
                  - name: envoy.on_demand
                    typed_config:
                      "@type": type.googleapis.com/envoy.extensions.filters.http.on_demand.v3.OnDemand
                      odcds:
                        source:
                          resource_api_version: V3
                          ads: {}
                        resources_locator:
                        timeout: 10s
                  - name: envoy.filters.http.router
                    typed_config:
                      "@type": type.googleapis.com/envoy.extensions.filters.http.router.v3.Router

Logs:

Include the access logs and the Envoy logs.

sorry that log from docker-compose is not well formatted.
according to the log, envoy received the request, but didn't send vhds and the request just failed with DeadlineExceeded Error.

 3146 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584374292Z [2022-09-27 10:28:39.584][176][debug][http] [source/common/http/conn_manager_impl.cc:909] [C3][S2297251804359213935] request headers complete (end_stream=false):
 3147 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584388577Z ':method', 'POST'
 3148 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584392821Z ':scheme', 'http'
 3149 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584397171Z ':path', '/my_sidecar.Helloworld/Tracert'
 3150 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584401841Z ':authority', 'my-sidecar_test'
 3151 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584405905Z 'content-type', 'application/grpc'
 3152 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584410184Z 'user-agent', 'grpc-go/1.49.0'
 3153 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584414249Z 'te', 'trailers'
 3154 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584417928Z 'grpc-timeout', '4980034u'
 3163 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584453745Z 'cid', 'sg'
 3167 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584468461Z



 3168 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584474036Z [2022-09-27 10:28:39.584][176][debug][connection] [./source/common/network/connection_impl.h:89] [C3] current connecting state: false
 3169 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584606780Z [2022-09-27 10:28:39.584][176][trace][http] [source/common/http/filter_manager.cc:525] [C3][S2297251804359213935] decode headers called: filter=envoy.on_demand status=1
 3170 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584619673Z [2022-09-27 10:28:39.584][176][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x5bfbd148980 for 300000ms, min is 300000ms
 3171 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584631976Z [2022-09-27 10:28:39.584][176][trace][http2] [source/common/http/http2/codec_impl.cc:1181] [C3] about to recv frame type=0, flags=1, stream_id=1
 3172 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584658143Z [2022-09-27 10:28:39.584][176][trace][http2] [source/common/http/http2/codec_impl.cc:1207] [C3] recv frame type=0
 3173 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584670994Z [2022-09-27 10:28:39.584][176][trace][http2] [source/common/http/http2/codec_impl.cc:2317] [C3] track inbound frame type=0 flags=1 length=26 padding_length=0
 3174 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584684683Z [2022-09-27 10:28:39.584][176][debug][http] [source/common/http/filter_manager.cc:790] [C3][S2297251804359213935] request end stream
 3175 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584691039Z [2022-09-27 10:28:39.584][176][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x5bfbd148980 for 300000ms, min is 300000ms
 3176 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584703084Z [2022-09-27 10:28:39.584][176][trace][http] [source/common/http/filter_manager.cc:657] [C3][S2297251804359213935] decode data called: filter=envoy.on_demand status=2
 3177 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:39.584715719Z [2022-09-27 10:28:39.584][176][trace][http2] [source/common/http/http2/codec_impl.cc:1086] [C3] dispatched 433 bytes
 3178 ^[[32;1mhelloworld-server_2_1        |^[[0m 2022-09-27T10:28:39.677073287Z  Debug INFO daemon_client.i:641 2022/9/27 10:28:39.676984452 ticktack
 3179 ^[[32;1mhelloworld-server_2_1        |^[[0m 2022-09-27T10:28:39.677111123Z  Debug INFO daemon_client.i:343 2022/9/27 10:28:39.677006336 beat
 3180 ^[[32;1mhelloworld-server_2_1        |^[[0m 2022-09-27T10:28:39.677666334Z  Debug INFO daemon_client.i:646 2022/9/27 10:28:39.677607111 ticktack Now 1664274519676944 NextTime 1664274524676944 Interval(s) 5 status error_code 0 error msg
 3181 ^[[35;1mhelloworld-server_3_1        |^[[0m 2022-09-27T10:28:39.710803584Z  Debug INFO daemon_client.i:641 2022/9/27 10:28:39.710719169 ticktack
 3182 ^[[35;1mhelloworld-server_3_1        |^[[0m 2022-09-27T10:28:39.710837187Z  Debug INFO daemon_client.i:343 2022/9/27 10:28:39.710746735 beat
 3183 ^[[33;1mhelloworld-server_1_1        |^[[0m 2022-09-27T10:28:39.710853389Z  Debug INFO daemon_client.i:641 2022/9/27 10:28:39.710774617 ticktack
 3184 ^[[33;1mhelloworld-server_1_1        |^[[0m 2022-09-27T10:28:39.710890410Z  Debug INFO daemon_client.i:343 2022/9/27 10:28:39.710794333 beat
 3185 ^[[35;1mhelloworld-server_3_1        |^[[0m 2022-09-27T10:28:39.711404629Z  Debug INFO daemon_client.i:646 2022/9/27 10:28:39.711356609 ticktack Now 1664274519710682 NextTime 1664274524710682 Interval(s) 5 status error_code 0 error msg
 3186 ^[[33;1mhelloworld-server_1_1        |^[[0m 2022-09-27T10:28:39.711396965Z  Debug INFO daemon_client.i:646 2022/9/27 10:28:39.711359831 ticktack Now 1664274519710742 NextTime 1664274524710742 Interval(s) 5 status error_code 0 error msg
 3187 ^[[36;1mhelloworld-server_0_1        |^[[0m 2022-09-27T10:28:39.715170090Z  Debug INFO daemon_client.i:641 2022/9/27 10:28:39.715097597 ticktack
 3188 ^[[36;1mhelloworld-server_0_1        |^[[0m 2022-09-27T10:28:39.715196900Z  Debug INFO daemon_client.i:343 2022/9/27 10:28:39.715120503 beat
 3189 ^[[36;1mhelloworld-server_0_1        |^[[0m 2022-09-27T10:28:39.715741395Z  Debug INFO daemon_client.i:646 2022/9/27 10:28:39.715706064 ticktack Now 1664274519715053 NextTime 1664274524715053 Interval(s) 5 status error_code 0 error msg
 3190 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.041582989Z  Debug INFO daemon_client.i:445 2022/9/27 10:28:44.524041279 refresh
 3191 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.043472051Z  Debug INFO daemon_client.i:323 2022/9/27 10:28:44.524043032 refreshBuckets Lookup reg_version: 17347 nodes { id: "ap-sg-1-general-x-1" ip: "10.129.112.12" port: "8080" status: STATUS_OK } nodes { id: "      ap-sg-1-general-x-2" ip: "10.129.112.6" port: "8080" status: STATUS_OK } nodes { id: "ap-sg-1-general-x-3" ip: "10.129.112.10" port: "8080" status: STATUS_OK }
 3192 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.043521767Z  Debug INFO daemon_client.i:760 2022/9/27 10:28:44.524043214 nodesToBuckets IP 10.129.112.12 Port 8080 grpc::Status(0:init 1:ok 2:shutdown) 1
 3193 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.043531329Z  Debug INFO daemon_client.i:764 2022/9/27 10:28:44.524043254 nodesToBuckets IP 10.129.112.12 Port 8080 Add
 3194 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.043538882Z  Debug INFO daemon_client.i:760 2022/9/27 10:28:44.524043290 nodesToBuckets IP 10.129.112.6 Port 8080 grpc::Status(0:init 1:ok 2:shutdown) 1
 3195 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.043546288Z  Debug INFO daemon_client.i:764 2022/9/27 10:28:44.524043311 nodesToBuckets IP 10.129.112.6 Port 8080 Add
 3196 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.043553198Z  Debug INFO daemon_client.i:760 2022/9/27 10:28:44.524043339 nodesToBuckets IP 10.129.112.10 Port 8080 grpc::Status(0:init 1:ok 2:shutdown) 1
 3197 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.043560424Z  Debug INFO daemon_client.i:764 2022/9/27 10:28:44.524043368 nodesToBuckets IP 10.129.112.10 Port 8080 Add
 3198 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.043940041Z  INFO bucket.h:130 2022/9/27 10:28:44.524043411 NeedRebalance NoNeedRebalance Version 17347
 3199 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.044012605Z  Debug INFO bucket.h:82 2022/9/27 10:28:44.524043436 Reset Reset 3
 3200 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.044053754Z  Debug INFO bucket.h:87 2022/9/27 10:28:44.524043459 Reset CopyMarkfail 1
 3201 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.044066533Z  Debug INFO bucket.h:87 2022/9/27 10:28:44.524043474 Reset CopyMarkfail 1
 3202 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.044087245Z  Debug INFO bucket.h:87 2022/9/27 10:28:44.524043516 Reset CopyMarkfail 1
 3203 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.044129044Z  INFO daemon_client.i:782 2022/9/27 10:28:44.524043546 resetBuckets src_version 17347 des_version 17347
 3204 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.044135802Z  Debug INFO daemon_client.i:448 2022/9/27 10:28:44.524043698 refresh Now 1664274524041162 NextTime 1664274584041162 Interval(s) 60
 3205 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.054324781Z  Debug INFO daemon_client.i:641 2022/9/27 10:28:44.524054235 ticktack
 3206 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.054361868Z  Debug INFO daemon_client.i:343 2022/9/27 10:28:44.524054266 beat
 3207 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.055283735Z  Debug INFO daemon_client.i:646 2022/9/27 10:28:44.524055230 ticktack Now 1664274524054183 NextTime 1664274529054183 Interval(s) 5 status error_code 0 error msg
 3208 ^[[33msocat-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.178614713Z 2022/09/27 10:28:44 socat[7] I transferred 180 bytes from 6 to 5
 3209 ^[[33msocat-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.178757622Z 2022/09/27 10:28:44 socat[7] I transferred 213 bytes from 5 to 6
 3210 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.200796404Z [2022-09-27 10:28:44.200][1][debug][main] [source/server/server.cc:251] flushing stats
 3211 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.232384351Z [2022-09-27 10:28:44.232][1][trace][upstream] [source/common/upstream/strict_dns_cluster.cc:105] starting async DNS resolution for control-plane
 3212 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.232423639Z [2022-09-27 10:28:44.232][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:341] dns resolution for control-plane started
 3213 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.232750137Z [2022-09-27 10:28:44.232][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:304] Setting DNS resolution timer for 5000 milliseconds
 3214 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.232767841Z [2022-09-27 10:28:44.232][1][trace][upstream] [source/common/upstream/strict_dns_cluster.cc:105] starting async DNS resolution for jaeger
 3215 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.232793633Z [2022-09-27 10:28:44.232][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:341] dns resolution for jaeger started
 3216 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.232920995Z [2022-09-27 10:28:44.232][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:304] Setting DNS resolution timer for 5000 milliseconds
 3217 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.232957405Z [2022-09-27 10:28:44.232][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:304] Setting DNS resolution timer for 5000 milliseconds
 3218 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.233004932Z [2022-09-27 10:28:44.232][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:304] Setting DNS resolution timer for 5000 milliseconds
 3219 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.233089789Z [2022-09-27 10:28:44.233][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:262] dns resolution for control-plane completed with status 0
 3220 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.233108964Z [2022-09-27 10:28:44.233][1][trace][upstream] [source/common/upstream/strict_dns_cluster.cc:113] async DNS resolution complete for control-plane
 3221 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.233165994Z [2022-09-27 10:28:44.233][1][debug][upstream] [source/common/upstream/upstream_impl.cc:274] transport socket match, socket default selected for host with address 172.23.0.2:18000
 3222 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.233232322Z [2022-09-27 10:28:44.233][1][debug][upstream] [source/common/upstream/strict_dns_cluster.cc:178] DNS refresh rate reset for control-plane, refresh rate 5000 ms
 3223 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.233285153Z [2022-09-27 10:28:44.233][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:262] dns resolution for jaeger completed with status 0
 3224 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.233311322Z [2022-09-27 10:28:44.233][1][trace][upstream] [source/common/upstream/strict_dns_cluster.cc:113] async DNS resolution complete for jaeger
 3225 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.233335454Z [2022-09-27 10:28:44.233][1][debug][upstream] [source/common/upstream/upstream_impl.cc:274] transport socket match, socket default selected for host with address 172.23.0.5:9411
 3226 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.233347079Z [2022-09-27 10:28:44.233][1][debug][upstream] [source/common/upstream/strict_dns_cluster.cc:178] DNS refresh rate reset for jaeger, refresh rate 5000 ms


 3227 ^[[35mhelloworld-frontend_0_1      |^[[0m 2022-09-27T10:28:44.564685984Z ERROR: logging before flag.Parse: E0927 10:28:44.564541       7 main.go:83] error: rpc error: code = DeadlineExceeded desc = context deadline exceeded
 3228 ^[[35mhelloworld-frontend_0_1      |^[[0m 2022-09-27T10:28:44.564731150Z [GIN] 2022/09/27 - 10:28:44 | 500 |   5.03012456s |      172.23.0.1 | POST     "/dev/tracert?cid=sg"


 3229 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.564722675Z [2022-09-27 10:28:44.564][176][trace][connection] [source/common/network/connection_impl.cc:563] [C3] socket event: 3
 3230 ^[[33menvoy-helloworld-frontend_1  |^[[0m 2022-09-27T10:28:44.564751287Z [2022-09-27 10:28:44.564][176][trace][connection] [source/common/network/connection_impl.cc:674] [C3] write ready

Note: If there are privacy concerns, sanitize the data prior to sharing.

Call Stack:

If the Envoy binary is crashing, a call stack is required. Please refer to the Bazel Stack trace documentation.