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.

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

ESPv2 fails to start when service config has duplicated camel_case name to json name mapping. #185

Closed
someone1 opened this issue Jun 4, 2020 · 19 comments · Fixed by #218
Assignees
Labels
bug Something isn't working

Comments

@someone1
Copy link

someone1 commented Jun 4, 2020

Moving discussion from Google Group:

I'm trying to run ESPv2 locally to replace ESPv1 during development. However, although ESPv1 works just fine, ESPv2 keeps bouncing the container. I've set my service account to project owner to eliminate permission issues.

Here is my Docker compose:

esp:
    image: gcr.io/endpoints-release/endpoints-runtime:2
    restart: unless-stopped
    ports:
      - "127.0.0.1:8089:8089"
    volumes:
      - ${USERPROFILE}/.google-application-credentials.json:/.google-application-credentials.json:ro
    environment:
      - GOOGLE_APPLICATION_CREDENTIALS=/.google-application-credentials.json
    command:
      - "--service=<SERVICE_NAME>"
      - "--rollout_strategy=managed"
      - "--listener_port=8089"
      - "--backend=http://dev:8081"
      - "--service_account_key=/.google-application-credentials.json"
      - "--cors_preset=basic"
      - "--cors_allow_origin=http://localhost:8080"
      - "--non_gcp"
      - "--enable_debug"
    links:
      - dev

Error log output (this constantly repeats):

I0604 18:19:01.038510      10 main.go:29] Output path: /tmp/bootstrap.json
I0604 18:19:01.038623      10 flags.go:105] Common options: {AdminAddress:0.0.0.0 AdminPort:0 DiscoveryPort:8790 
Node:ESPv2 DisableTracing:true TracingProjectId: TracingStackdriverAddress: TracingSamplingRate:0.001 
TracingIncomingContext: TracingOutgoingContext: TracingMaxNumAttributes:32 TracingMaxNumAnnotations:32 
TracingMaxNumMessageEvents:128 TracingMaxNumLinks:128 NonGCP:false HttpRequestTimeout:5s 
MetadataURL:http://169.254.169.254/computeMetadata IamURL:https://iamcredentials.googleapis.com 
ServiceControlCredentials:<nil> BackendAuthCredentials:<nil>}
I0604 18:19:01.039175      10 flags.go:39] ADS Bootstrapper options: {CommonOptions:{AdminAddress:0.0.0.0 
AdminPort:0 DiscoveryPort:8790 Node:ESPv2 DisableTracing:true TracingProjectId: TracingStackdriverAddress: 
TracingSamplingRate:0.001 TracingIncomingContext: TracingOutgoingContext: TracingMaxNumAttributes:32 
TracingMaxNumAnnotations:32 TracingMaxNumMessageEvents:128 TracingMaxNumLinks:128 NonGCP:false 
HttpRequestTimeout:5s MetadataURL:http://169.254.169.254/computeMetadata 
IamURL:https://iamcredentials.googleapis.com ServiceControlCredentials:<nil> BackendAuthCredentials:<nil>} 
AdsConnectTimeout:10s DiscoveryAddress:127.0.0.1:8790}

CRITICAL: Config Manager is down, killing all processes.

And the standard log output (this also repeats):

Starting Config Manager with args: ['bin/configmanager', '--logtostderr', '--backend_address', 'http://dev:8081', '--rollout_strategy', 'managed', '--v', '1', '--listener_port', '8089', '--service', '<SERVICE NAME>', '--disable_tracing', '--cors_preset', 'basic', '--cors_allow_origin', 'http://localhost:8080', '--cors_allow_origin_regex', '', '--cors_allow_methods', 'GET, POST, PUT, PATCH, DELETE, OPTIONS', '--cors_allow_headers', 'DNT,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Range,Authorization', '--cors_expose_headers', 'Content-Length,Content-Range', '--service_account_key', '/.google-application-credentials.json', '--non_gcp', '--suppress_envoy_headers=false']
['bin/bootstrap', '--logtostderr', '--admin_port', '0', '--disable_tracing', '/tmp/bootstrap.json']
I0604 18:19:01.034435       6 flags.go:105] Common options: {AdminAddress:0.0.0.0 AdminPort:8001 DiscoveryPort:8790 Node:ESPv2 DisableTracing:true TracingProjectId: TracingStackdriverAddress: TracingSamplingRate:0.001 TracingIncomingContext: TracingOutgoingContext: TracingMaxNumAttributes:32 TracingMaxNumAnnotations:32 TracingMaxNumMessageEvents:128 TracingMaxNumLinks:128 NonGCP:true HttpRequestTimeout:5s MetadataURL:http://169.254.169.254/computeMetadata IamURL:https://iamcredentials.googleapis.com ServiceControlCredentials:<nil> BackendAuthCredentials:<nil>}
I0604 18:19:01.034903       6 flags.go:173] Config Generator options: {CommonOptions:{AdminAddress:0.0.0.0 AdminPort:8001 DiscoveryPort:8790 Node:ESPv2 DisableTracing:true TracingProjectId: TracingStackdriverAddress: TracingSamplingRate:0.001 TracingIncomingContext: TracingOutgoingContext: TracingMaxNumAttributes:32 TracingMaxNumAnnotations:32 TracingMaxNumMessageEvents:128 TracingMaxNumLinks:128 NonGCP:true HttpRequestTimeout:5s MetadataURL:http://169.254.169.254/computeMetadata IamURL:https://iamcredentials.googleapis.com ServiceControlCredentials:<nil> BackendAuthCredentials:<nil>} CorsAllowCredentials:false CorsAllowHeaders:DNT,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Range,Authorization CorsAllowMethods:GET, POST, PUT, PATCH, DELETE, OPTIONS CorsAllowOrigin:http://localhost:8080 CorsAllowOriginRegex: CorsExposeHeaders:Content-Length,Content-Range CorsPreset:basic BackendDnsLookupFamily:auto ClusterConnectTimeout:20s BackendAddress:http://dev:8081 ListenerAddress:0.0.0.0 Healthz: ServiceManagementURL:https://servicemanagement.googleapis.com ServiceControlURL:https://servicecontrol.googleapis.com ListenerPort:8089 SslServerCertPath: SslClientCertPath: SslMinimumProtocol: SslMaximumProtocol: EnableHSTS:false RootCertsPath:/etc/ssl/certs/ca-certificates.crt DnsResolverAddresses: ServiceAccountKey:/.google-application-credentials.json SkipJwtAuthnFilter:false SkipServiceControlFilter:false AccessLog: AccessLogFormat: EnvoyUseRemoteAddress:false EnvoyXffNumTrustedHops:2 LogJwtPayloads: LogRequestHeaders: LogResponseHeaders: MinStreamReportIntervalMs:0 SuppressEnvoyHeaders:false UnderscoresInHeaders:false ServiceControlNetworkFailOpen:true JwksCacheDurationInS:300 ScCheckTimeoutMs:0 ScQuotaTimeoutMs:0 ScReportTimeoutMs:0 ScCheckRetries:-1 ScQuotaRetries:-1 ScReportRetries:-1 ComputePlatformOverride: TranscodingAlwaysPrintPrimitiveFields:false TranscodingAlwaysPrintEnumsAsInts:false TranscodingPreserveProtoFieldNames:false TranscodingIgnoreQueryParameters: TranscodingIgnoreUnknownQueryParameters:false}
Starting Envoy with args: ['bin/envoy', '-c', '/tmp/bootstrap.json', '--disable-hot-restart', '--log-format %L%m%d %T.%e %t envoy] [%t][%n]%v', '--log-format-escaped', '-l debug']
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:293] initializing epoch 0 (hot restart version=disabled)
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:295] statically linked extensions:
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.stats_sinks: envoy.metrics_service, envoy.stat_sinks.metrics_service
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.retry_host_predicates: envoy.retry_host_predicates.previous_hosts
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.retry_priorities: envoy.retry_priorities.previous_priorities
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.udp_listeners: raw_udp_listener
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.access_loggers: envoy.access_loggers.file, envoy.access_loggers.http_grpc, envoy.file_access_log, envoy.http_grpc_access_log
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.clusters: envoy.cluster.eds, envoy.cluster.logical_dns, envoy.cluster.original_dst, envoy.cluster.static, envoy.cluster.strict_dns
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.resolvers: envoy.ip
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.grpc_credentials: envoy.grpc_credentials.default, envoy.grpc_credentials.file_based_metadata
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.transport_sockets.downstream: envoy.transport_sockets.alts, envoy.transport_sockets.raw_buffer, envoy.transport_sockets.tap, envoy.transport_sockets.tls, raw_buffer, tls
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.tracers: envoy.tracers.opencensus
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.filters.listener: envoy.filters.listener.original_dst, envoy.filters.listener.proxy_protocol, envoy.filters.listener.tls_inspector, envoy.listener.original_dst, envoy.listener.proxy_protocol, envoy.listener.tls_inspector
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.transport_sockets.upstream: envoy.transport_sockets.alts, envoy.transport_sockets.raw_buffer, envoy.transport_sockets.tap, envoy.transport_sockets.tls, raw_buffer, tls
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.resource_monitors: envoy.resource_monitors.fixed_heap, envoy.resource_monitors.injected_resource
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.filters.http: envoy.buffer, envoy.cors, envoy.ext_authz, envoy.fault, envoy.filters.http.backend_auth, envoy.filters.http.backend_routing, envoy.filters.http.buffer, envoy.filters.http.cors, envoy.filters.http.ext_authz, envoy.filters.http.fault, envoy.filters.http.grpc_http1_bridge, envoy.filters.http.grpc_json_transcoder, envoy.filters.http.grpc_stats, envoy.filters.http.grpc_web, envoy.filters.http.gzip, envoy.filters.http.header_to_metadata, envoy.filters.http.health_check, envoy.filters.http.ip_tagging, envoy.filters.http.jwt_authn, envoy.filters.http.path_matcher, envoy.filters.http.ratelimit, envoy.filters.http.rbac, envoy.filters.http.router, envoy.filters.http.service_control, envoy.grpc_http1_bridge, envoy.grpc_json_transcoder, envoy.grpc_web, envoy.gzip, envoy.health_check, envoy.ip_tagging, envoy.rate_limit, envoy.router
I0604 18:19:01.089 22 envoy] [22][main][external/envoy/source/server/server.cc:297]   envoy.filters.network: envoy.client_ssl_auth, envoy.ext_authz, envoy.filters.network.client_ssl_auth, envoy.filters.network.ext_authz, envoy.filters.network.http_connection_manager, envoy.filters.network.ratelimit, envoy.filters.network.rbac, envoy.filters.network.sni_cluster, envoy.filters.network.tcp_proxy, envoy.http_connection_manager, envoy.ratelimit, envoy.tcp_proxy
W0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/server.cc:384] No admin address given, so no admin HTTP server started.
D0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/overload_manager_impl.cc:184] No overload action is configured for envoy.overload_actions.shrink_heap.
D0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/overload_manager_impl.cc:184] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
D0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/overload_manager_impl.cc:184] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
D0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/overload_manager_impl.cc:184] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
D0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/overload_manager_impl.cc:184] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
D0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/overload_manager_impl.cc:184] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
D0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/overload_manager_impl.cc:184] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
D0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/overload_manager_impl.cc:184] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
D0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/overload_manager_impl.cc:184] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
I0604 18:19:01.098 22 envoy] [22][main][external/envoy/source/server/server.cc:525] runtime: layers:\n  - name: base\n    static_layer:\n      {}\n  - name: admin\n    admin_layer:\n      {}
I0604 18:19:01.099 22 envoy] [22][config][external/envoy/source/server/configuration_impl.cc:103] loading tracing configuration
I0604 18:19:01.099 22 envoy] [22][config][external/envoy/source/server/configuration_impl.cc:69] loading 0 static secret(s)
I0604 18:19:01.099 22 envoy] [22][config][external/envoy/source/server/configuration_impl.cc:75] loading 1 cluster(s)
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:978] adding TLS initial cluster ads_cluster
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:146] DNS hosts have changed for 127.0.0.1
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:971] initializing Primary cluster ads_cluster completed
D0604 18:19:01.100 22 envoy] [22][init][external/envoy/source/common/init/manager_impl.cc:45] init manager Cluster ads_cluster contains no targets
D0604 18:19:01.100 22 envoy] [22][init][external/envoy/source/common/init/watcher_impl.cc:14] init manager Cluster ads_cluster initialized, notifying ClusterImplBase
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:1137] membership update for TLS cluster ads_cluster added 1 removed 0
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:105] cm init: init complete: cluster=ads_cluster primary=0 secondary=0
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:125] maybe finish initialize state: 0
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:77] cm init: adding: cluster=ads_cluster primary=0 secondary=0
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:125] maybe finish initialize state: 1
D0604 18:19:01.100 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:134] maybe finish initialize primary init clusters empty: true
D0604 18:19:01.101 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:47] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.service.discovery.v3.DiscoveryRequest) returns (stream .envoy.service.discovery.v3.DiscoveryResponse);

D0604 18:19:01.101 22 envoy] [22][router][external/envoy/source/common/router/router.cc:435] [C0][S1482019712714766912] cluster \'ads_cluster\' match for URL \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'
D0604 18:19:01.101 22 envoy] [22][router][external/envoy/source/common/router/router.cc:590] [C0][S1482019712714766912] router decoding headers:\n\':method\', \'POST\'\n\':path\', \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'\n\':authority\', \'ads_cluster\'\n\':scheme\', \'http\'\n\'te\', \'trailers\'\n\'content-type\', \'application/grpc\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'

D0604 18:19:01.101 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:346] queueing request due to no available connections
D0604 18:19:01.101 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:47] creating a new connection
D0604 18:19:01.101 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:35] [C0] connecting
D0604 18:19:01.101 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:753] [C0] connecting to 127.0.0.1:8790
D0604 18:19:01.101 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:762] [C0] connection in progress
D0604 18:19:01.101 22 envoy] [22][http2][external/envoy/source/common/http/http2/codec_impl.cc:1011] [C0] updating connection-level initial window size to 268435456
I0604 18:19:01.101 22 envoy] [22][config][external/envoy/source/server/configuration_impl.cc:79] loading 0 listener(s)
I0604 18:19:01.101 22 envoy] [22][config][external/envoy/source/server/configuration_impl.cc:129] loading stats sink configuration
D0604 18:19:01.101 22 envoy] [22][init][external/envoy/source/common/init/manager_impl.cc:20] added target LDS to init manager Server
D0604 18:19:01.101 22 envoy] [22][init][external/envoy/source/common/init/manager_impl.cc:45] init manager RTDS contains no targets
D0604 18:19:01.101 22 envoy] [22][init][external/envoy/source/common/init/watcher_impl.cc:14] init manager RTDS initialized, notifying RDTS
I0604 18:19:01.101 22 envoy] [22][runtime][external/envoy/source/common/runtime/runtime_impl.cc:526] RTDS has finished initialization
D0604 18:19:01.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:196] continue initializing secondary clusters
D0604 18:19:01.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:125] maybe finish initialize state: 2
D0604 18:19:01.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:134] maybe finish initialize primary init clusters empty: true
D0604 18:19:01.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:149] maybe finish initialize secondary init clusters empty: true
D0604 18:19:01.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:172] maybe finish initialize cds api ready: true
I0604 18:19:01.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:174] cm init: initializing cds
D0604 18:19:01.101 22 envoy] [22][config][external/envoy/source/common/config/grpc_mux_impl.cc:75] gRPC mux addWatch for type.googleapis.com/envoy.config.cluster.v3.Cluster
D0604 18:19:01.101 27 envoy] [27][grpc][external/envoy/source/common/grpc/google_async_client_impl.cc:48] completionThread running
I0604 18:19:01.102 22 envoy] [22][main][external/envoy/source/server/server.cc:622] starting main dispatch loop
D0604 18:19:01.102 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:625] [C0] delayed connection error: 111
D0604 18:19:01.102 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:208] [C0] closing socket: 0
D0604 18:19:01.102 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:92] [C0] disconnect. resetting 0 pending requests
D0604 18:19:01.102 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:265] [C0] client disconnected, failure reason: 
D0604 18:19:01.102 22 envoy] [22][router][external/envoy/source/common/router/router.cc:1055] [C0][S1482019712714766912] upstream reset: reset reason connection failure
D0604 18:19:01.103 22 envoy] [22][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=true):\n\':status\', \'200\'\n\'content-type\', \'application/grpc\'\n\'grpc-status\', \'14\'\n\'grpc-message\', \'upstream connect error or disconnect/reset before headers. reset reason: connection failure\'

W0604 18:19:01.103 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:92] StreamAggregatedResources gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers. reset reason: connection failure
D0604 18:19:01.103 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.cluster.v3.Cluster failed
D0604 18:19:01.132 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:47] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.service.discovery.v3.DiscoveryRequest) returns (stream .envoy.service.discovery.v3.DiscoveryResponse);

D0604 18:19:01.132 22 envoy] [22][router][external/envoy/source/common/router/router.cc:435] [C0][S17192125370729511656] cluster \'ads_cluster\' match for URL \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'
D0604 18:19:01.132 22 envoy] [22][router][external/envoy/source/common/router/router.cc:590] [C0][S17192125370729511656] router decoding headers:\n\':method\', \'POST\'\n\':path\', \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'\n\':authority\', \'ads_cluster\'\n\':scheme\', \'http\'\n\'te\', \'trailers\'\n\'content-type\', \'application/grpc\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'

D0604 18:19:01.132 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:346] queueing request due to no available connections
D0604 18:19:01.132 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:47] creating a new connection
D0604 18:19:01.132 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:35] [C1] connecting
D0604 18:19:01.132 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:753] [C1] connecting to 127.0.0.1:8790
D0604 18:19:01.132 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:762] [C1] connection in progress
D0604 18:19:01.132 22 envoy] [22][http2][external/envoy/source/common/http/http2/codec_impl.cc:1011] [C1] updating connection-level initial window size to 268435456
D0604 18:19:01.133 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:625] [C1] delayed connection error: 111
D0604 18:19:01.133 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:208] [C1] closing socket: 0
D0604 18:19:01.133 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:92] [C1] disconnect. resetting 0 pending requests
D0604 18:19:01.133 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:265] [C1] client disconnected, failure reason: 
D0604 18:19:01.133 22 envoy] [22][router][external/envoy/source/common/router/router.cc:1055] [C0][S17192125370729511656] upstream reset: reset reason connection failure
D0604 18:19:01.133 22 envoy] [22][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=true):\n\':status\', \'200\'\n\'content-type\', \'application/grpc\'\n\'grpc-status\', \'14\'\n\'grpc-message\', \'upstream connect error or disconnect/reset before headers. reset reason: connection failure\'

W0604 18:19:01.133 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:92] StreamAggregatedResources gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers. reset reason: connection failure
D0604 18:19:01.133 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.cluster.v3.Cluster failed
D0604 18:19:01.346 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:47] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.service.discovery.v3.DiscoveryRequest) returns (stream .envoy.service.discovery.v3.DiscoveryResponse);

D0604 18:19:01.346 22 envoy] [22][router][external/envoy/source/common/router/router.cc:435] [C0][S13862197817187926874] cluster \'ads_cluster\' match for URL \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'
D0604 18:19:01.346 22 envoy] [22][router][external/envoy/source/common/router/router.cc:590] [C0][S13862197817187926874] router decoding headers:\n\':method\', \'POST\'\n\':path\', \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'\n\':authority\', \'ads_cluster\'\n\':scheme\', \'http\'\n\'te\', \'trailers\'\n\'content-type\', \'application/grpc\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'

D0604 18:19:01.346 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:346] queueing request due to no available connections
D0604 18:19:01.346 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:47] creating a new connection
D0604 18:19:01.346 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:35] [C2] connecting
D0604 18:19:01.346 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:753] [C2] connecting to 127.0.0.1:8790
D0604 18:19:01.346 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:762] [C2] connection in progress
D0604 18:19:01.346 22 envoy] [22][http2][external/envoy/source/common/http/http2/codec_impl.cc:1011] [C2] updating connection-level initial window size to 268435456
D0604 18:19:01.347 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:625] [C2] delayed connection error: 111
D0604 18:19:01.347 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:208] [C2] closing socket: 0
D0604 18:19:01.347 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:92] [C2] disconnect. resetting 0 pending requests
D0604 18:19:01.347 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:265] [C2] client disconnected, failure reason: 
D0604 18:19:01.347 22 envoy] [22][router][external/envoy/source/common/router/router.cc:1055] [C0][S13862197817187926874] upstream reset: reset reason connection failure
D0604 18:19:01.347 22 envoy] [22][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=true):\n\':status\', \'200\'\n\'content-type\', \'application/grpc\'\n\'grpc-status\', \'14\'\n\'grpc-message\', \'upstream connect error or disconnect/reset before headers. reset reason: connection failure\'

W0604 18:19:01.347 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:92] StreamAggregatedResources gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers. reset reason: connection failure
D0604 18:19:01.347 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.cluster.v3.Cluster failed
D0604 18:19:01.553 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:47] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.service.discovery.v3.DiscoveryRequest) returns (stream .envoy.service.discovery.v3.DiscoveryResponse);

D0604 18:19:01.553 22 envoy] [22][router][external/envoy/source/common/router/router.cc:435] [C0][S2820004545228429044] cluster \'ads_cluster\' match for URL \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'
D0604 18:19:01.553 22 envoy] [22][router][external/envoy/source/common/router/router.cc:590] [C0][S2820004545228429044] router decoding headers:\n\':method\', \'POST\'\n\':path\', \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'\n\':authority\', \'ads_cluster\'\n\':scheme\', \'http\'\n\'te\', \'trailers\'\n\'content-type\', \'application/grpc\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'

D0604 18:19:01.553 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:346] queueing request due to no available connections
D0604 18:19:01.553 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:47] creating a new connection
D0604 18:19:01.553 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:35] [C3] connecting
D0604 18:19:01.553 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:753] [C3] connecting to 127.0.0.1:8790
D0604 18:19:01.553 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:762] [C3] connection in progress
D0604 18:19:01.553 22 envoy] [22][http2][external/envoy/source/common/http/http2/codec_impl.cc:1011] [C3] updating connection-level initial window size to 268435456
D0604 18:19:01.553 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:625] [C3] delayed connection error: 111
D0604 18:19:01.553 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:208] [C3] closing socket: 0
D0604 18:19:01.553 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:92] [C3] disconnect. resetting 0 pending requests
D0604 18:19:01.553 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:265] [C3] client disconnected, failure reason: 
D0604 18:19:01.553 22 envoy] [22][router][external/envoy/source/common/router/router.cc:1055] [C0][S2820004545228429044] upstream reset: reset reason connection failure
D0604 18:19:01.553 22 envoy] [22][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=true):\n\':status\', \'200\'\n\'content-type\', \'application/grpc\'\n\'grpc-status\', \'14\'\n\'grpc-message\', \'upstream connect error or disconnect/reset before headers. reset reason: connection failure\'

W0604 18:19:01.554 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:92] StreamAggregatedResources gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers. reset reason: connection failure
D0604 18:19:01.554 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.cluster.v3.Cluster failed
F0604 18:19:01.815178       6 server.go:52] fail to initialize config manager: fail to fetch and apply the startup service config, fail to initialize ServiceInfo, detected two types with same snake_name (number_value) but mistmatching json_name (numberValue, number_value)
D0604 18:19:03.198 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:47] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.service.discovery.v3.DiscoveryRequest) returns (stream .envoy.service.discovery.v3.DiscoveryResponse);

D0604 18:19:03.198 22 envoy] [22][router][external/envoy/source/common/router/router.cc:435] [C0][S4438559899739963454] cluster \'ads_cluster\' match for URL \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'
D0604 18:19:03.198 22 envoy] [22][router][external/envoy/source/common/router/router.cc:590] [C0][S4438559899739963454] router decoding headers:\n\':method\', \'POST\'\n\':path\', \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'\n\':authority\', \'ads_cluster\'\n\':scheme\', \'http\'\n\'te\', \'trailers\'\n\'content-type\', \'application/grpc\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'

D0604 18:19:03.198 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:346] queueing request due to no available connections
D0604 18:19:03.198 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:47] creating a new connection
D0604 18:19:03.198 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:35] [C4] connecting
D0604 18:19:03.198 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:753] [C4] connecting to 127.0.0.1:8790
D0604 18:19:03.198 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:762] [C4] connection in progress
D0604 18:19:03.198 22 envoy] [22][http2][external/envoy/source/common/http/http2/codec_impl.cc:1011] [C4] updating connection-level initial window size to 268435456
D0604 18:19:03.198 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:625] [C4] delayed connection error: 111
D0604 18:19:03.198 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:208] [C4] closing socket: 0
D0604 18:19:03.198 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:92] [C4] disconnect. resetting 0 pending requests
D0604 18:19:03.198 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:265] [C4] client disconnected, failure reason: 
D0604 18:19:03.198 22 envoy] [22][router][external/envoy/source/common/router/router.cc:1055] [C0][S4438559899739963454] upstream reset: reset reason connection failure
D0604 18:19:03.198 22 envoy] [22][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=true):\n\':status\', \'200\'\n\'content-type\', \'application/grpc\'\n\'grpc-status\', \'14\'\n\'grpc-message\', \'upstream connect error or disconnect/reset before headers. reset reason: connection failure\'

W0604 18:19:03.198 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:92] StreamAggregatedResources gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers. reset reason: connection failure
D0604 18:19:03.198 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.cluster.v3.Cluster failed
D0604 18:19:06.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:06.102 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:06.103 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:19:06.103 22 envoy] [22][main][external/envoy/source/server/server.cc:197] Envoy is not fully initialized, skipping histogram merge and flushing stats
D0604 18:19:06.412 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:47] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.service.discovery.v3.DiscoveryRequest) returns (stream .envoy.service.discovery.v3.DiscoveryResponse);

D0604 18:19:06.412 22 envoy] [22][router][external/envoy/source/common/router/router.cc:435] [C0][S11388764262586255397] cluster \'ads_cluster\' match for URL \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'
D0604 18:19:06.412 22 envoy] [22][router][external/envoy/source/common/router/router.cc:590] [C0][S11388764262586255397] router decoding headers:\n\':method\', \'POST\'\n\':path\', \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'\n\':authority\', \'ads_cluster\'\n\':scheme\', \'http\'\n\'te\', \'trailers\'\n\'content-type\', \'application/grpc\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'

D0604 18:19:06.412 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:346] queueing request due to no available connections
D0604 18:19:06.412 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:47] creating a new connection
D0604 18:19:06.412 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:35] [C5] connecting
D0604 18:19:06.412 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:753] [C5] connecting to 127.0.0.1:8790
D0604 18:19:06.412 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:762] [C5] connection in progress
D0604 18:19:06.412 22 envoy] [22][http2][external/envoy/source/common/http/http2/codec_impl.cc:1011] [C5] updating connection-level initial window size to 268435456
D0604 18:19:06.412 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:625] [C5] delayed connection error: 111
D0604 18:19:06.412 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:208] [C5] closing socket: 0
D0604 18:19:06.412 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:92] [C5] disconnect. resetting 0 pending requests
D0604 18:19:06.413 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:265] [C5] client disconnected, failure reason: 
D0604 18:19:06.413 22 envoy] [22][router][external/envoy/source/common/router/router.cc:1055] [C0][S11388764262586255397] upstream reset: reset reason connection failure
D0604 18:19:06.413 22 envoy] [22][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=true):\n\':status\', \'200\'\n\'content-type\', \'application/grpc\'\n\'grpc-status\', \'14\'\n\'grpc-message\', \'upstream connect error or disconnect/reset before headers. reset reason: connection failure\'

W0604 18:19:06.413 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:92] StreamAggregatedResources gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers. reset reason: connection failure
D0604 18:19:06.413 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.cluster.v3.Cluster failed
D0604 18:19:08.445 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:47] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.service.discovery.v3.DiscoveryRequest) returns (stream .envoy.service.discovery.v3.DiscoveryResponse);

D0604 18:19:08.445 22 envoy] [22][router][external/envoy/source/common/router/router.cc:435] [C0][S7430516812441038328] cluster \'ads_cluster\' match for URL \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'
D0604 18:19:08.445 22 envoy] [22][router][external/envoy/source/common/router/router.cc:590] [C0][S7430516812441038328] router decoding headers:\n\':method\', \'POST\'\n\':path\', \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'\n\':authority\', \'ads_cluster\'\n\':scheme\', \'http\'\n\'te\', \'trailers\'\n\'content-type\', \'application/grpc\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'

D0604 18:19:08.445 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:346] queueing request due to no available connections
D0604 18:19:08.445 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:47] creating a new connection
D0604 18:19:08.445 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:35] [C6] connecting
D0604 18:19:08.445 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:753] [C6] connecting to 127.0.0.1:8790
D0604 18:19:08.446 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:762] [C6] connection in progress
D0604 18:19:08.446 22 envoy] [22][http2][external/envoy/source/common/http/http2/codec_impl.cc:1011] [C6] updating connection-level initial window size to 268435456
D0604 18:19:08.446 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:625] [C6] delayed connection error: 111
D0604 18:19:08.446 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:208] [C6] closing socket: 0
D0604 18:19:08.446 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:92] [C6] disconnect. resetting 0 pending requests
D0604 18:19:08.446 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:265] [C6] client disconnected, failure reason: 
D0604 18:19:08.446 22 envoy] [22][router][external/envoy/source/common/router/router.cc:1055] [C0][S7430516812441038328] upstream reset: reset reason connection failure
D0604 18:19:08.446 22 envoy] [22][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=true):\n\':status\', \'200\'\n\'content-type\', \'application/grpc\'\n\'grpc-status\', \'14\'\n\'grpc-message\', \'upstream connect error or disconnect/reset before headers. reset reason: connection failure\'

W0604 18:19:08.446 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:92] StreamAggregatedResources gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers. reset reason: connection failure
D0604 18:19:08.446 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.cluster.v3.Cluster failed
D0604 18:19:11.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:11.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:11.103 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:19:11.103 22 envoy] [22][main][external/envoy/source/server/server.cc:197] Envoy is not fully initialized, skipping histogram merge and flushing stats
D0604 18:19:16.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:125] maybe finish initialize state: 4
D0604 18:19:16.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:134] maybe finish initialize primary init clusters empty: true
D0604 18:19:16.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:149] maybe finish initialize secondary init clusters empty: true
D0604 18:19:16.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:172] maybe finish initialize cds api ready: true
I0604 18:19:16.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:178] cm init: all clusters initialized
D0604 18:19:16.102 22 envoy] [22][config][external/envoy/source/common/config/grpc_mux_impl.cc:98] Pausing discovery requests for type.googleapis.com/envoy.api.v2.RouteConfiguration
I0604 18:19:16.102 22 envoy] [22][main][external/envoy/source/server/server.cc:601] all clusters initialized. initializing init manager
D0604 18:19:16.102 22 envoy] [22][init][external/envoy/source/common/init/manager_impl.cc:49] init manager Server initializing
D0604 18:19:16.102 22 envoy] [22][init][external/envoy/source/common/init/target_impl.cc:15] init manager Server initializing target LDS
D0604 18:19:16.102 22 envoy] [22][config][external/envoy/source/common/config/grpc_mux_impl.cc:75] gRPC mux addWatch for type.googleapis.com/envoy.config.listener.v3.Listener
D0604 18:19:16.102 22 envoy] [22][config][external/envoy/source/common/config/grpc_mux_impl.cc:32] No stream available to sendDiscoveryRequest for type.googleapis.com/envoy.config.listener.v3.Listener
D0604 18:19:16.102 22 envoy] [22][config][external/envoy/source/common/config/grpc_mux_impl.cc:106] Resuming discovery requests for type.googleapis.com/envoy.api.v2.RouteConfiguration
D0604 18:19:16.102 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:16.102 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:16.104 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:19:16.104 22 envoy] [22][main][external/envoy/source/server/server.cc:197] Envoy is not fully initialized, skipping histogram merge and flushing stats
D0604 18:19:21.102 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:21.102 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:21.105 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:19:21.105 22 envoy] [22][main][external/envoy/source/server/server.cc:197] Envoy is not fully initialized, skipping histogram merge and flushing stats
D0604 18:19:26.102 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:26.102 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:26.105 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:19:26.105 22 envoy] [22][main][external/envoy/source/server/server.cc:197] Envoy is not fully initialized, skipping histogram merge and flushing stats
D0604 18:19:27.089 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:47] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.service.discovery.v3.DiscoveryRequest) returns (stream .envoy.service.discovery.v3.DiscoveryResponse);

D0604 18:19:27.089 22 envoy] [22][router][external/envoy/source/common/router/router.cc:435] [C0][S6807818758608856795] cluster \'ads_cluster\' match for URL \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'
D0604 18:19:27.089 22 envoy] [22][router][external/envoy/source/common/router/router.cc:590] [C0][S6807818758608856795] router decoding headers:\n\':method\', \'POST\'\n\':path\', \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'\n\':authority\', \'ads_cluster\'\n\':scheme\', \'http\'\n\'te\', \'trailers\'\n\'content-type\', \'application/grpc\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'

D0604 18:19:27.089 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:346] queueing request due to no available connections
D0604 18:19:27.089 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:47] creating a new connection
D0604 18:19:27.089 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:35] [C7] connecting
D0604 18:19:27.089 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:753] [C7] connecting to 127.0.0.1:8790
D0604 18:19:27.089 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:762] [C7] connection in progress
D0604 18:19:27.089 22 envoy] [22][http2][external/envoy/source/common/http/http2/codec_impl.cc:1011] [C7] updating connection-level initial window size to 268435456
D0604 18:19:27.089 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:625] [C7] delayed connection error: 111
D0604 18:19:27.089 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:208] [C7] closing socket: 0
D0604 18:19:27.089 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:92] [C7] disconnect. resetting 0 pending requests
D0604 18:19:27.089 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:265] [C7] client disconnected, failure reason: 
D0604 18:19:27.089 22 envoy] [22][router][external/envoy/source/common/router/router.cc:1055] [C0][S6807818758608856795] upstream reset: reset reason connection failure
D0604 18:19:27.090 22 envoy] [22][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=true):\n\':status\', \'200\'\n\'content-type\', \'application/grpc\'\n\'grpc-status\', \'14\'\n\'grpc-message\', \'upstream connect error or disconnect/reset before headers. reset reason: connection failure\'

W0604 18:19:27.090 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:92] StreamAggregatedResources gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers. reset reason: connection failure
D0604 18:19:27.090 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.listener.v3.Listener failed
D0604 18:19:27.090 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.cluster.v3.Cluster failed
D0604 18:19:31.102 22 envoy] [22][init][external/envoy/source/common/init/watcher_impl.cc:14] target LDS initialized, notifying init manager Server
D0604 18:19:31.102 22 envoy] [22][init][external/envoy/source/common/init/watcher_impl.cc:14] init manager Server initialized, notifying RunHelper
I0604 18:19:31.102 22 envoy] [22][config][external/envoy/source/server/listener_manager_impl.cc:836] all dependencies initialized. starting workers
D0604 18:19:31.102 22 envoy] [22][config][external/envoy/source/server/listener_manager_impl.cc:847] starting worker 0
D0604 18:19:31.102 22 envoy] [22][config][external/envoy/source/server/listener_manager_impl.cc:847] starting worker 1
D0604 18:19:31.102 34 envoy] [34][main][external/envoy/source/server/worker_impl.cc:111] worker entering dispatch loop
D0604 18:19:31.102 22 envoy] [22][config][external/envoy/source/server/listener_manager_impl.cc:847] starting worker 2
D0604 18:19:31.102 34 envoy] [34][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:978] adding TLS initial cluster ads_cluster
D0604 18:19:31.102 35 envoy] [35][main][external/envoy/source/server/worker_impl.cc:111] worker entering dispatch loop
D0604 18:19:31.102 36 envoy] [36][grpc][external/envoy/source/common/grpc/google_async_client_impl.cc:48] completionThread running
D0604 18:19:31.102 37 envoy] [37][main][external/envoy/source/server/worker_impl.cc:111] worker entering dispatch loop
D0604 18:19:31.102 34 envoy] [34][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:1137] membership update for TLS cluster ads_cluster added 1 removed 0
D0604 18:19:31.102 22 envoy] [22][config][external/envoy/source/server/listener_manager_impl.cc:847] starting worker 3
D0604 18:19:31.102 35 envoy] [35][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:978] adding TLS initial cluster ads_cluster
D0604 18:19:31.103 37 envoy] [37][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:978] adding TLS initial cluster ads_cluster
D0604 18:19:31.103 38 envoy] [38][grpc][external/envoy/source/common/grpc/google_async_client_impl.cc:48] completionThread running
D0604 18:19:31.103 22 envoy] [22][config][external/envoy/source/server/listener_manager_impl.cc:847] starting worker 4
D0604 18:19:31.103 37 envoy] [37][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:1137] membership update for TLS cluster ads_cluster added 1 removed 0
D0604 18:19:31.103 35 envoy] [35][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:1137] membership update for TLS cluster ads_cluster added 1 removed 0
D0604 18:19:31.103 22 envoy] [22][config][external/envoy/source/server/listener_manager_impl.cc:847] starting worker 5
D0604 18:19:31.103 40 envoy] [40][main][external/envoy/source/server/worker_impl.cc:111] worker entering dispatch loop
D0604 18:19:31.103 22 envoy] [22][config][external/envoy/source/server/listener_manager_impl.cc:847] starting worker 6
D0604 18:19:31.103 39 envoy] [39][grpc][external/envoy/source/common/grpc/google_async_client_impl.cc:48] completionThread running
D0604 18:19:31.103 42 envoy] [42][main][external/envoy/source/server/worker_impl.cc:111] worker entering dispatch loop
D0604 18:19:31.103 41 envoy] [41][main][external/envoy/source/server/worker_impl.cc:111] worker entering dispatch loop
D0604 18:19:31.103 22 envoy] [22][config][external/envoy/source/server/listener_manager_impl.cc:847] starting worker 7
D0604 18:19:31.103 43 envoy] [43][main][external/envoy/source/server/worker_impl.cc:111] worker entering dispatch loop
D0604 18:19:31.103 40 envoy] [40][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:978] adding TLS initial cluster ads_cluster
D0604 18:19:31.104 40 envoy] [40][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:1137] membership update for TLS cluster ads_cluster added 1 removed 0
D0604 18:19:31.103 44 envoy] [44][grpc][external/envoy/source/common/grpc/google_async_client_impl.cc:48] completionThread running
D0604 18:19:31.104 42 envoy] [42][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:978] adding TLS initial cluster ads_cluster
D0604 18:19:31.104 41 envoy] [41][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:978] adding TLS initial cluster ads_cluster
D0604 18:19:31.104 43 envoy] [43][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:978] adding TLS initial cluster ads_cluster
D0604 18:19:31.104 42 envoy] [42][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:1137] membership update for TLS cluster ads_cluster added 1 removed 0
D0604 18:19:31.104 46 envoy] [46][grpc][external/envoy/source/common/grpc/google_async_client_impl.cc:48] completionThread running
D0604 18:19:31.104 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:31.104 43 envoy] [43][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:1137] membership update for TLS cluster ads_cluster added 1 removed 0
D0604 18:19:31.104 47 envoy] [47][main][external/envoy/source/server/worker_impl.cc:111] worker entering dispatch loop
D0604 18:19:31.104 41 envoy] [41][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:1137] membership update for TLS cluster ads_cluster added 1 removed 0
D0604 18:19:31.104 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:31.104 45 envoy] [45][grpc][external/envoy/source/common/grpc/google_async_client_impl.cc:48] completionThread running
D0604 18:19:31.104 47 envoy] [47][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:978] adding TLS initial cluster ads_cluster
D0604 18:19:31.104 49 envoy] [49][grpc][external/envoy/source/common/grpc/google_async_client_impl.cc:48] completionThread running
D0604 18:19:31.104 47 envoy] [47][upstream][external/envoy/source/common/upstream/cluster_manager_impl.cc:1137] membership update for TLS cluster ads_cluster added 1 removed 0
D0604 18:19:31.104 48 envoy] [48][grpc][external/envoy/source/common/grpc/google_async_client_impl.cc:48] completionThread running
D0604 18:19:31.107 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:19:36.101 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:36.102 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:36.108 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:19:39.925 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:47] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.service.discovery.v3.DiscoveryRequest) returns (stream .envoy.service.discovery.v3.DiscoveryResponse);

D0604 18:19:39.925 22 envoy] [22][router][external/envoy/source/common/router/router.cc:435] [C0][S12521283791827806850] cluster \'ads_cluster\' match for URL \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'
D0604 18:19:39.925 22 envoy] [22][router][external/envoy/source/common/router/router.cc:590] [C0][S12521283791827806850] router decoding headers:\n\':method\', \'POST\'\n\':path\', \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'\n\':authority\', \'ads_cluster\'\n\':scheme\', \'http\'\n\'te\', \'trailers\'\n\'content-type\', \'application/grpc\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'

D0604 18:19:39.925 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:346] queueing request due to no available connections
D0604 18:19:39.925 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:47] creating a new connection
D0604 18:19:39.925 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:35] [C8] connecting
D0604 18:19:39.925 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:753] [C8] connecting to 127.0.0.1:8790
D0604 18:19:39.926 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:762] [C8] connection in progress
D0604 18:19:39.926 22 envoy] [22][http2][external/envoy/source/common/http/http2/codec_impl.cc:1011] [C8] updating connection-level initial window size to 268435456
D0604 18:19:39.926 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:625] [C8] delayed connection error: 111
D0604 18:19:39.926 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:208] [C8] closing socket: 0
D0604 18:19:39.926 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:92] [C8] disconnect. resetting 0 pending requests
D0604 18:19:39.926 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:265] [C8] client disconnected, failure reason: 
D0604 18:19:39.926 22 envoy] [22][router][external/envoy/source/common/router/router.cc:1055] [C0][S12521283791827806850] upstream reset: reset reason connection failure
D0604 18:19:39.926 22 envoy] [22][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=true):\n\':status\', \'200\'\n\'content-type\', \'application/grpc\'\n\'grpc-status\', \'14\'\n\'grpc-message\', \'upstream connect error or disconnect/reset before headers. reset reason: connection failure\'

W0604 18:19:39.926 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:92] StreamAggregatedResources gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers. reset reason: connection failure
D0604 18:19:39.926 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.listener.v3.Listener failed
D0604 18:19:39.926 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.cluster.v3.Cluster failed
D0604 18:19:41.103 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:41.103 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:41.109 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:19:46.104 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:46.104 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:46.109 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:19:51.104 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:51.104 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:51.109 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:19:56.104 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:19:56.104 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:19:56.109 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
D0604 18:20:00.870 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:47] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.service.discovery.v3.DiscoveryRequest) returns (stream .envoy.service.discovery.v3.DiscoveryResponse);

D0604 18:20:00.870 22 envoy] [22][router][external/envoy/source/common/router/router.cc:435] [C0][S11297151677618551664] cluster \'ads_cluster\' match for URL \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'
D0604 18:20:00.870 22 envoy] [22][router][external/envoy/source/common/router/router.cc:590] [C0][S11297151677618551664] router decoding headers:\n\':method\', \'POST\'\n\':path\', \'/envoy.service.discovery.v3.AggregatedDiscoveryService/StreamAggregatedResources\'\n\':authority\', \'ads_cluster\'\n\':scheme\', \'http\'\n\'te\', \'trailers\'\n\'content-type\', \'application/grpc\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'

D0604 18:20:00.870 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:346] queueing request due to no available connections
D0604 18:20:00.870 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:47] creating a new connection
D0604 18:20:00.871 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:35] [C9] connecting
D0604 18:20:00.871 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:753] [C9] connecting to 127.0.0.1:8790
D0604 18:20:00.871 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:762] [C9] connection in progress
D0604 18:20:00.871 22 envoy] [22][http2][external/envoy/source/common/http/http2/codec_impl.cc:1011] [C9] updating connection-level initial window size to 268435456
D0604 18:20:00.871 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:625] [C9] delayed connection error: 111
D0604 18:20:00.871 22 envoy] [22][connection][external/envoy/source/common/network/connection_impl.cc:208] [C9] closing socket: 0
D0604 18:20:00.871 22 envoy] [22][client][external/envoy/source/common/http/codec_client.cc:92] [C9] disconnect. resetting 0 pending requests
D0604 18:20:00.871 22 envoy] [22][pool][external/envoy/source/common/http/conn_pool_base.cc:265] [C9] client disconnected, failure reason: 
D0604 18:20:00.871 22 envoy] [22][router][external/envoy/source/common/router/router.cc:1055] [C0][S11297151677618551664] upstream reset: reset reason connection failure
D0604 18:20:00.871 22 envoy] [22][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=true):\n\':status\', \'200\'\n\'content-type\', \'application/grpc\'\n\'grpc-status\', \'14\'\n\'grpc-message\', \'upstream connect error or disconnect/reset before headers. reset reason: connection failure\'

W0604 18:20:00.871 22 envoy] [22][config][bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:92] StreamAggregatedResources gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers. reset reason: connection failure
D0604 18:20:00.871 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.listener.v3.Listener failed
D0604 18:20:00.871 22 envoy] [22][config][external/envoy/source/common/config/grpc_subscription_impl.cc:90] gRPC update for type.googleapis.com/envoy.config.cluster.v3.Cluster failed
D0604 18:20:01.104 22 envoy] [22][upstream][external/envoy/source/common/upstream/upstream_impl.cc:278] transport socket match, socket default selected for host with address 127.0.0.1:8790
D0604 18:20:01.105 22 envoy] [22][upstream][external/envoy/source/common/upstream/strict_dns_cluster.cc:167] DNS refresh rate reset for 127.0.0.1, refresh rate 5000 ms
D0604 18:20:01.110 22 envoy] [22][main][external/envoy/source/server/server.cc:187] flushing stats
@JLXIA
Copy link
Contributor

JLXIA commented Jun 4, 2020

I would suspect that "--backend=http://dev:8081" is not correct.

please make sure that your local backend is listening on port 8081, and your docker network is correct.

@qiwzhang
Copy link
Contributor

qiwzhang commented Jun 4, 2020

I found this error:
server.go: fail to initialize config manager: fail to fetch and apply the startup service config, fail to initialize ServiceInfo, detected two types with same snake_name (number_value) but mistmatching json_name (numberValue, number_value)

Somehow, either your service_name is wrong,
or your service_account json file is wrong, or the service account is not allow to fetch the service config file from Google service management.

@qiwzhang
Copy link
Contributor

qiwzhang commented Jun 4, 2020

@TAOXUY there is not much info for this error, even under --enable_debug flag. Can we add more debug info for easy debugging?

@qiwzhang
Copy link
Contributor

qiwzhang commented Jun 4, 2020

@someone1 did you remove your service name in the log, or you are actually pass in this flag as

'--service', ''

This is the first log line:

Starting Config Manager with args: ['bin/configmanager', '--logtostderr', '--backend_address', 'http://dev:8081', '--rollout_strategy', 'managed', '--v', '1', '--listener_port', '8089', '--service', '', '--disable_tracing', '--cors_preset', 'basic', '--cors_allow_origin', 'http://localhost:8080', '--cors_allow_origin_regex', '', '--cors_allow_methods', 'GET, POST, PUT, PATCH, DELETE, OPTIONS', '--cors_allow_headers', 'DNT,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Range,Authorization', '--cors_expose_headers', 'Content-Length,Content-Range', '--service_account_key', '/.google-application-credentials.json', '--non_gcp', '--suppress_envoy_headers=false']
['bin/bootstrap', '--logtostderr', '--admin_port', '0', '--disable_tracing', '/tmp/bootstrap.json']

@someone1
Copy link
Author

someone1 commented Jun 4, 2020

I would suspect that "--backend=http://dev:8081" is not correct.

please make sure that your local backend is listening on port 8081, and your docker network is correct.

This is the same backend I use and work with ESPv1 - and like ESPv1 it shouldn't need to be up and running for the container to launch (it keeps crashing).

I found this error:
server.go: fail to initialize config manager: fail to fetch and apply the startup service config, fail to initialize ServiceInfo, detected two types with same snake_name (number_value) but mistmatching json_name (numberValue, number_value)

Somehow, either your service_name is wrong,
or your service_account json file is wrong, or the service account is not allow to fetch the service config file from Google service management.

I'm using the same service account JSON file and configuration version I use with ESPv1 - the service account has full project owner permissions just in case.

I also tried launching this on CloudRun with the same result using the gcloud_build_image:

 Deployment failed
 ERROR: (gcloud.beta.run.deploy) Cloud Run error: Container failed to start. Failed to start and then listen on the port defined by the PORT environment variable. Logs for this revision might contain more information.

Logs from Cloud Run

2020-06-04 15:05:41.539 EDT
I0604 19:05:41.539433 4 main.go:29] Output path: /tmp/bootstrap.json
2020-06-04 15:05:41.540 EDT
I0604 19:05:41.539788 4 flags.go:105] Common options: {AdminAddress:0.0.0.0 AdminPort:0 DiscoveryPort:8790 Node:ESPv2 DisableTracing:false TracingProjectId: TracingStackdriverAddress: TracingSamplingRate:0.9 TracingIncomingContext:grpc-trace-bin TracingOutgoingContext:grpc-trace-bin TracingMaxNumAttributes:32 TracingMaxNumAnnotations:32 TracingMaxNumMessageEvents:128 TracingMaxNumLinks:128 NonGCP:false HttpRequestTimeout:5s MetadataURL:http://169.254.169.254/computeMetadata IamURL:https://iamcredentials.googleapis.com ServiceControlCredentials:<nil> BackendAuthCredentials:<nil>}
2020-06-04 15:05:41.540 EDT
I0604 19:05:41.540360 4 flags.go:39] ADS Bootstrapper options: {CommonOptions:{AdminAddress:0.0.0.0 AdminPort:0 DiscoveryPort:8790 Node:ESPv2 DisableTracing:false TracingProjectId: TracingStackdriverAddress: TracingSamplingRate:0.9 TracingIncomingContext:grpc-trace-bin TracingOutgoingContext:grpc-trace-bin TracingMaxNumAttributes:32 TracingMaxNumAnnotations:32 TracingMaxNumMessageEvents:128 TracingMaxNumLinks:128 NonGCP:false HttpRequestTimeout:5s MetadataURL:http://169.254.169.254/computeMetadata IamURL:https://iamcredentials.googleapis.com ServiceControlCredentials:<nil> BackendAuthCredentials:<nil>} AdsConnectTimeout:10s DiscoveryAddress:127.0.0.1:8790}
2020-06-04 15:05:41.540 EDT
I0604 19:05:41.540561 4 tracing.go:62] tracing_project_id was not specified, attempting to fetch it from GCP Metadata server
2020-06-04 15:05:41.893 EDT
Starting Config Manager with args: ['bin/configmanager', '--logtostderr', '--backend_address', 'http://127.0.0.1:8082', '--rollout_strategy', 'fixed', '--v', '0', '--listener_port', '8080', '--service_json_path', '/etc/endpoints/service.json', '--compute_platform_override', 'Cloud Run(ESPv2)']
2020-06-04 15:05:41.893 EDT
['bin/bootstrap', '--logtostderr', '--admin_port', '0', '--tracing_incoming_context', 'grpc-trace-bin', '--tracing_outgoing_context', 'grpc-trace-bin', '--tracing_sample_rate', '.9', '/tmp/bootstrap.json']
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.516770 2 flags.go:105] Common options: {AdminAddress:0.0.0.0 AdminPort:8001 DiscoveryPort:8790 Node:ESPv2 DisableTracing:false TracingProjectId: TracingStackdriverAddress: TracingSamplingRate:0.001 TracingIncomingContext: TracingOutgoingContext: TracingMaxNumAttributes:32 TracingMaxNumAnnotations:32 TracingMaxNumMessageEvents:128 TracingMaxNumLinks:128 NonGCP:false HttpRequestTimeout:5s MetadataURL:http://169.254.169.254/computeMetadata IamURL:https://iamcredentials.googleapis.com ServiceControlCredentials:<nil> BackendAuthCredentials:<nil>}
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.518197 2 flags.go:173] Config Generator options: {CommonOptions:{AdminAddress:0.0.0.0 AdminPort:8001 DiscoveryPort:8790 Node:ESPv2 DisableTracing:false TracingProjectId: TracingStackdriverAddress: TracingSamplingRate:0.001 TracingIncomingContext: TracingOutgoingContext: TracingMaxNumAttributes:32 TracingMaxNumAnnotations:32 TracingMaxNumMessageEvents:128 TracingMaxNumLinks:128 NonGCP:false HttpRequestTimeout:5s MetadataURL:http://169.254.169.254/computeMetadata IamURL:https://iamcredentials.googleapis.com ServiceControlCredentials:<nil> BackendAuthCredentials:<nil>} CorsAllowCredentials:false CorsAllowHeaders: CorsAllowMethods: CorsAllowOrigin: CorsAllowOriginRegex: CorsExposeHeaders: CorsPreset: BackendDnsLookupFamily:auto ClusterConnectTimeout:20s BackendAddress:http://127.0.0.1:8082 ListenerAddress:0.0.0.0 Healthz: ServiceManagementURL:https://servicemanagement.googleapis.com ServiceControlURL:https://servicecontrol.googleapis.com ListenerPort:8080 SslServerCertPath: SslClientCertPath: SslMinimumProtocol: SslMaximumProtocol: EnableHSTS:false RootCertsPath:/etc/ssl/certs/ca-certificates.crt DnsResolverAddresses: ServiceAccountKey: SkipJwtAuthnFilter:false SkipServiceControlFilter:false AccessLog: AccessLogFormat: EnvoyUseRemoteAddress:false EnvoyXffNumTrustedHops:2 LogJwtPayloads: LogRequestHeaders: LogResponseHeaders: MinStreamReportIntervalMs:0 SuppressEnvoyHeaders:true UnderscoresInHeaders:false ServiceControlNetworkFailOpen:true JwksCacheDurationInS:300 ScCheckTimeoutMs:0 ScQuotaTimeoutMs:0 ScReportTimeoutMs:0 ScCheckRetries:-1 ScQuotaRetries:-1 ScReportRetries:-1 ComputePlatformOverride:Cloud Run(ESPv2) TranscodingAlwaysPrintPrimitiveFields:false TranscodingAlwaysPrintEnumsAsInts:false TranscodingPreserveProtoFieldNames:false TranscodingIgnoreQueryParameters: TranscodingIgnoreUnknownQueryParameters:false}
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.518457 2 server.go:46] running on GCP, initializing metadata fetcher
2020-06-04 15:05:41.893 EDT
Starting Envoy with args: ['bin/envoy', '-c', '/tmp/bootstrap.json', '--disable-hot-restart', '--log-format %L%m%d %T.%e %t envoy] [%t][%n]%v', '--log-format-escaped']
2020-06-04 15:05:41.893 EDT
F0604 19:05:41.642205 2 server.go:52] fail to initialize config manager: fail to initialize ServiceInfo, detected two types with same snake_name (number_value) but mistmatching json_name (numberValue, number_value)
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:293] initializing epoch 0 (hot restart version=disabled)
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:295] statically linked extensions:
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.filters.network: envoy.client_ssl_auth, envoy.ext_authz, envoy.filters.network.client_ssl_auth, envoy.filters.network.ext_authz, envoy.filters.network.http_connection_manager, envoy.filters.network.ratelimit, envoy.filters.network.rbac, envoy.filters.network.sni_cluster, envoy.filters.network.tcp_proxy, envoy.http_connection_manager, envoy.ratelimit, envoy.tcp_proxy
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.transport_sockets.upstream: envoy.transport_sockets.alts, envoy.transport_sockets.raw_buffer, envoy.transport_sockets.tap, envoy.transport_sockets.tls, raw_buffer, tls
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.grpc_credentials: envoy.grpc_credentials.default, envoy.grpc_credentials.file_based_metadata
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.filters.listener: envoy.filters.listener.original_dst, envoy.filters.listener.proxy_protocol, envoy.filters.listener.tls_inspector, envoy.listener.original_dst, envoy.listener.proxy_protocol, envoy.listener.tls_inspector
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.resolvers: envoy.ip
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.stats_sinks: envoy.metrics_service, envoy.stat_sinks.metrics_service
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.clusters: envoy.cluster.eds, envoy.cluster.logical_dns, envoy.cluster.original_dst, envoy.cluster.static, envoy.cluster.strict_dns
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.tracers: envoy.tracers.opencensus
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.udp_listeners: raw_udp_listener
2020-06-04 15:05:41.893 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.retry_host_predicates: envoy.retry_host_predicates.previous_hosts
2020-06-04 15:05:41.894 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.transport_sockets.downstream: envoy.transport_sockets.alts, envoy.transport_sockets.raw_buffer, envoy.transport_sockets.tap, envoy.transport_sockets.tls, raw_buffer, tls
2020-06-04 15:05:41.894 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.retry_priorities: envoy.retry_priorities.previous_priorities
2020-06-04 15:05:41.895 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.filters.http: envoy.buffer, envoy.cors, envoy.ext_authz, envoy.fault, envoy.filters.http.backend_auth, envoy.filters.http.backend_routing, envoy.filters.http.buffer, envoy.filters.http.cors, envoy.filters.http.ext_authz, envoy.filters.http.fault, envoy.filters.http.grpc_http1_bridge, envoy.filters.http.grpc_json_transcoder, envoy.filters.http.grpc_stats, envoy.filters.http.grpc_web, envoy.filters.http.gzip, envoy.filters.http.header_to_metadata, envoy.filters.http.health_check, envoy.filters.http.ip_tagging, envoy.filters.http.jwt_authn, envoy.filters.http.path_matcher, envoy.filters.http.ratelimit, envoy.filters.http.rbac, envoy.filters.http.router, envoy.filters.http.service_control, envoy.grpc_http1_bridge, envoy.grpc_json_transcoder, envoy.grpc_web, envoy.gzip, envoy.health_check, envoy.ip_tagging, envoy.rate_limit, envoy.router
2020-06-04 15:05:41.895 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.resource_monitors: envoy.resource_monitors.fixed_heap, envoy.resource_monitors.injected_resource
2020-06-04 15:05:41.895 EDT
I0604 19:05:41.880 17 envoy] [17][main][external/envoy/source/server/server.cc:297] envoy.access_loggers: envoy.access_loggers.file, envoy.access_loggers.http_grpc, envoy.file_access_log, envoy.http_grpc_access_log
2020-06-04 15:05:41.895 EDT
W0604 19:05:41.891 17 envoy] [17][main][external/envoy/source/server/server.cc:384] No admin address given, so no admin HTTP server started.
2020-06-04 15:05:41.895 EDT
I0604 19:05:41.892 17 envoy] [17][main][external/envoy/source/server/server.cc:525] runtime: layers:\n - name: base\n static_layer:\n {}\n - name: admin\n admin_layer:\n {}
2020-06-04 15:05:41.895 EDT
I0604 19:05:41.892 17 envoy] [17][config][external/envoy/source/server/configuration_impl.cc:103] loading tracing configuration
2020-06-04 15:05:41.895 EDT
I0604 19:05:41.892 17 envoy] [17][config][external/envoy/source/server/configuration_impl.cc:114] validating default server-wide tracing driver: envoy.tracers.opencensus
2020-06-04 15:05:41.895 EDT
I0604 19:05:41.892 17 envoy] [17][config][external/envoy/source/server/configuration_impl.cc:69] loading 0 static secret(s)
2020-06-04 15:06:41.627 EDT
CRITICAL: Config Manager is down, killing all processes.

@someone1 did you remove your service name in the log, or you are actually pass in this flag as

'--service', ''

This is the first log line:

Starting Config Manager with args: ['bin/configmanager', '--logtostderr', '--backend_address', 'http://dev:8081', '--rollout_strategy', 'managed', '--v', '1', '--listener_port', '8089', '--service', '', '--disable_tracing', '--cors_preset', 'basic', '--cors_allow_origin', 'http://localhost:8080', '--cors_allow_origin_regex', '', '--cors_allow_methods', 'GET, POST, PUT, PATCH, DELETE, OPTIONS', '--cors_allow_headers', 'DNT,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Range,Authorization', '--cors_expose_headers', 'Content-Length,Content-Range', '--service_account_key', '/.google-application-credentials.json', '--non_gcp', '--suppress_envoy_headers=false']
['bin/bootstrap', '--logtostderr', '--admin_port', '0', '--disable_tracing', '/tmp/bootstrap.json']

I removed it from the log

@someone1
Copy link
Author

someone1 commented Jun 4, 2020

I guess given that it doesn't work both on Cloud Run using the build step and locally, this may be related to the OpenAPI spec not loading properly in ESPv2? It works as-is in ESPv1.

Feel free to adjust the title as necessary.

@nareddyt
Copy link
Contributor

nareddyt commented Jun 4, 2020

detected two types with same snake_name (number_value) but mistmatching json_name (numberValue, number_value)

This is related to some validation I added in #118. If you're running into this error, then this could result in undefined behavior with OpenAPI path templating.

Could you share the open API spec and the service config with us? If needed, you can also email it directly to me (nareddyt@google.com). You can download the service config with this command:

gcloud endpoints configs describe \
  --project="nareddyt-cloud-esf" \
  --service="espv2-grpc-lrnm3ejpeq-uc.a.run.app" \
  --format=json \
  > service.json

@someone1
Copy link
Author

someone1 commented Jun 4, 2020

I'll email it over shortly!

Some Updates from testing locally:

  • It seems to launch without issue with the 2.7 release and hits my backend (have to check something about the ESP header being different though)
  • The 2.8 release also seems to load, though it only works for the first request which it always responds with 401 unauthorized and a response body of UNAUTHENTICATED:Calling Google Service Control API failed with: 401 and body: ���Ð�Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project. Every subsequent request hangs indefinitely.
  • The 2.9, 2.10, and 2.11 releases fail to launch the container completely (keeps bouncing)

For now I'll pin the version to 2.7

@someone1
Copy link
Author

someone1 commented Jun 4, 2020

I do see this in the logs with 2.7:

E0604 20:14:26.444054       6 rollout_id_change_detector.go:65] error occurred when checking new rollout id, fail to fetch new rollout id, http call to POST https://servicecontrol.googleapis.com/v1/services/web-api-dot-digital-advice-dev.appspot.com:report returns not 200 OK: 403 Forbidden

Again - I'm using the same exact JSON credentials file as I do with ESPv1 and it has the project owner role so I'm not sure what other underlying issue there may be. It obviously does load the configuration since it's passing requests through to my backend and notifies me if I navigate to an unknown path.

@nareddyt
Copy link
Contributor

nareddyt commented Jun 4, 2020

Basically what this error is saying is that if you have a x-google-backend configured for CONSTANT_ADDRESS, then for a path template with the snake_name:

GET /test1/{number_value}

ESPv2 is unsure which jsonName query param to translate it to:

  • GET /test1?numberValue=val
  • GET /test2?number_value=val

ESPv2 will end up choosing based on the ordering of the service config, which is not well defined. As far as I can tell, this was never validated in ESPv1.

I believe this change is in 2.9.0, which would explain why 2.7.0 works. Unsure about the error in 2.8.0, seems unrelated.

@qiwzhang
Copy link
Contributor

qiwzhang commented Jun 4, 2020

@nareddyt with that snake_name case error, is it just a warning, or we bailout the configmgr?
It should be just a warning.

We are going to add more debug log in configmgr to help to debug this problem.

@nareddyt
Copy link
Contributor

nareddyt commented Jun 5, 2020

@qiwzhang no, this will cause config manager to bail out. I think this is the correct behavior. Otherwise, ESPv2 will not be predictable in which query param to use for CONSTANT ADDRESS. This was bought up during the security review.

Maybe we can relax the constraint so this validation error only happens when the service config has CONSTANT ADDRESS path translation. Currently, the error occurs even if the user only configures APPEND_PATH_TO_ADDRESS, which doesn't make sense (query params are not required for this path translation).

@someone1 emailed me the OpenAPI spec and service config, so I want to take a closer look.

@qiwzhang
Copy link
Contributor

qiwzhang commented Jun 5, 2020

@nareddyt I filed b/158262661

@nareddyt nareddyt self-assigned this Jun 9, 2020
@nareddyt nareddyt added the bug Something isn't working label Jun 9, 2020
@nareddyt
Copy link
Contributor

nareddyt commented Jun 9, 2020

We discussed offline how to better map query params in ESPv2 to prevent this duplication from occurring. I will implement next week, hopefully get is fixed by the next release.

@rhodee
Copy link

rhodee commented Jun 19, 2020

Hi -

It is my understanding it is not possible to run the ESPv2 containers locally for gRPC backends. Is this an accurate understanding? If that is not the case, is there a docker compose or example repo to follow along?

Thank you.

@qiwzhang
Copy link
Contributor

Running ESPv2 with docker run in localhost is possible.

sudo docker run \
    --name=esp \
    --detach \
    --publish=80:8080 \
    --net=esp_net \
    gcr.io/endpoints-release/endpoints-runtime:2 \
    --service=[SERVICE_NAME] \
    --rollout_strategy=managed \
    --backend=grpc:://echo:8080

The step is similar to this doc

@qiwzhang
Copy link
Contributor

As specific for @someone1 original issue, we have some bugs in handling camel_case to jsonName conversion. Specifically, his service config some how has some duplicated mapping from camel_case names to json names, ESPv2 fails with such service cofnig, ESPv1 is fine.

We are work on the fix for this case. It has nothing to do with running ESPv2 locally.

@qiwzhang qiwzhang changed the title Running ESPv2 Locally with OpenAPI not working ESPv2 fails to start when service config has duplicated camel_case name to json name mapping. Jun 19, 2020
nareddyt added a commit that referenced this issue Jul 14, 2020
…ead of global (#218)

In OpenAPI specs, a path template jsonName may conflict with the jsonName of well known `google.protobuf.*` types. To prevent this, define the snake_to_json segment mapping per operation instead of globally in the path matcher filter. Then the validation of name conflicts will only be per-operation, greatly making the validation less strict.

Also optimize when this needs to be configured in the path matcher config. We only pass this when we need path parameter extraction under constant address backend routing.

Diff is too large already. I will follow-up with PRs for:
- Adding integration tests.
- Incrementing api version (breaking API change).

Ref: https://groups.google.com/u/1/g/google-cloud-endpoints/c/hxyuDx1yrvQ
Closes #185

Signed-off-by: Teju Nareddy <nareddyt@google.com>
@someone1
Copy link
Author

someone1 commented Jul 23, 2020

@nareddyt - should this be working now with 2.14? It works when run on Cloud Run but not locally. It seems to get a lot further, actually downloading the config and listening to requests and the previous snake_case error message no longer appears. However, I still only get a single request before the entire container locks up, and it never reaches my backend:

HTTP Response (Status Code 500):

{"code":500,"message":"INTERNAL:Calling Google Service Control API failed with: 401 and body: \b\u0010\u0012Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project."}

Relevant logs around the request:

D0723 02:03:33.267 53 envoy] [53][http][external/envoy/source/common/http/conn_manager_impl.cc:261] [C3] new stream
D0723 02:03:33.267 53 envoy] [53][http][external/envoy/source/common/http/conn_manager_impl.cc:808] [C3][S14536850401322214170] request headers complete (end_stream=true):\n\':authority\', \'localhost:8089\'\n\':path\', \'/v1alpha/accounts?key=<removed>\'\n\':method\', \'GET\'\n\'connection\', \'keep-alive\'\n\'pragma\', \'no-cache\'\n\'cache-control\', \'no-cache\'\n\'authorization\', \'Bearer <removed>\'

D0723 02:03:33.267 53 envoy] [53][http][external/envoy/source/common/http/conn_manager_impl.cc:1377] [C3][S14536850401322214170] request end stream
D0723 02:03:33.267 53 envoy] [53][jwt][external/envoy/source/extensions/filters/http/jwt_authn/filter.cc:127] Called Filter : setDecoderFilterCallbacks
D0723 02:03:33.267 53 envoy] [53][filter][src/envoy/http/path_matcher/filter.cc:81] matched operation: v1alpha.web_api_dot_project_id_appspot_com.Web_ListAccounts
D0723 02:03:33.267 53 envoy] [53][jwt][external/envoy/source/extensions/filters/http/jwt_authn/filter.cc:49] Called Filter : decodeHeaders
D0723 02:03:33.267 53 envoy] [53][jwt][bazel-out/k8-opt/bin/external/envoy/source/extensions/filters/http/jwt_authn/_virtual_includes/filter_config_interface/extensions/filters/http/jwt_authn/filter_config.h:117] use filter state value v1alpha.web_api_dot_project_id_appspot_com.Web_ListAccounts to find verifier.
D0723 02:03:33.267 53 envoy] [53][jwt][external/envoy/source/extensions/filters/http/jwt_authn/extractor.cc:188] extract authorizationBearer 
D0723 02:03:33.267 53 envoy] [53][jwt][external/envoy/source/extensions/filters/http/jwt_authn/extractor.cc:188] extract x-goog-iap-jwt-assertion
D0723 02:03:33.267 53 envoy] [53][jwt][external/envoy/source/extensions/filters/http/jwt_authn/authenticator.cc:127] auth0_jwk: JWT authentication starts (allow_failed=false), tokens size=1
D0723 02:03:33.267 53 envoy] [53][jwt][external/envoy/source/extensions/filters/http/jwt_authn/authenticator.cc:138] auth0_jwk: startVerify: tokens size 1
D0723 02:03:33.267 53 envoy] [53][jwt][external/envoy/source/extensions/filters/http/jwt_authn/authenticator.cc:149] auth0_jwk: Verifying JWT token of issuer https://<project-id>.auth0.com/
D0723 02:03:33.267 53 envoy] [53][filter][external/envoy/source/extensions/filters/http/common/jwks_fetcher.cc:55] fetch pubkey from [uri = https://<project-id>.auth0.com/.well-known/jwks.json]: start
D0723 02:03:33.267 53 envoy] [53][router][external/envoy/source/common/router/router.cc:426] [C0][S12502690874350086838] cluster \'<project-id>.auth0.com:443\' match for URL \'/.well-known/jwks.json\'
D0723 02:03:33.267 53 envoy] [53][router][external/envoy/source/common/router/router.cc:583] [C0][S12502690874350086838] router decoding headers:\n\':path\', \'/.well-known/jwks.json\'\n\':authority\', \'<project-id>.auth0.com\'\n\':method\', \'GET\'\n\':scheme\', \'https\'\n\'x-envoy-internal\', \'true\'\n\'x-forwarded-for\', \'172.18.0.8\'\n\'x-envoy-expected-rq-timeout-ms\', \'30000\'

D0723 02:03:33.267 53 envoy] [53][pool][external/envoy/source/common/http/conn_pool_base.cc:71] queueing request due to no available connections
D0723 02:03:33.267 53 envoy] [53][pool][external/envoy/source/common/conn_pool/conn_pool_base.cc:53] creating a new connection
D0723 02:03:33.268 53 envoy] [53][client][external/envoy/source/common/http/codec_client.cc:35] [C4] connecting
D0723 02:03:33.268 53 envoy] [53][connection][external/envoy/source/common/network/connection_impl.cc:753] [C4] connecting to 35.165.199.195:443
D0723 02:03:33.268 53 envoy] [53][connection][external/envoy/source/common/network/connection_impl.cc:769] [C4] connection in progress
D0723 02:03:33.268 53 envoy] [53][jwt][external/envoy/source/extensions/filters/http/jwt_authn/filter.cc:76] Called Filter : decodeHeaders Stop
D0723 02:03:33.333 53 envoy] [53][connection][external/envoy/source/common/network/connection_impl.cc:616] [C4] connected
D0723 02:03:33.333 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C4] handshake expecting read
D0723 02:03:33.399 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C4] handshake expecting read
D0723 02:03:33.399 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C4] handshake expecting read
D0723 02:03:33.399 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C4] handshake expecting read
D0723 02:03:33.401 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C4] handshake expecting read
D0723 02:03:33.401 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C4] handshake expecting read
D0723 02:03:33.466 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:176] [C4] handshake complete
D0723 02:03:33.466 53 envoy] [53][client][external/envoy/source/common/http/codec_client.cc:73] [C4] connected
D0723 02:03:33.466 53 envoy] [53][pool][external/envoy/source/common/conn_pool/conn_pool_base.cc:146] [C4] attaching to next request
D0723 02:03:33.466 53 envoy] [53][pool][external/envoy/source/common/conn_pool/conn_pool_base.cc:73] [C4] creating stream
D0723 02:03:33.466 53 envoy] [53][router][external/envoy/source/common/router/upstream_request.cc:342] [C0][S12502690874350086838] pool ready
D0723 02:03:33.513 53 envoy] [53][conn_handler][external/envoy/source/server/connection_handler_impl.cc:422] [C5] new connection
D0723 02:03:33.545 53 envoy] [53][router][external/envoy/source/common/router/router.cc:1153] [C0][S12502690874350086838] upstream headers complete: end_stream=false
D0723 02:03:33.545 53 envoy] [53][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=false):\n\':status\', \'200\'\n\'date\', \'Thu, 23 Jul 2020 02:03:33 GMT\'\n\'content-type\', \'application/json; charset=utf-8\'\n\'content-length\', \'3160\'\n\'connection\', \'keep-alive\'\n\'server\', \'nginx\'\n\'vary\', \'Accept-Encoding,Accept-Encoding\'\n\'ot-tracer-spanid\', \'7ce79021366dfbbf\'\n\'ot-tracer-traceid\', \'072b59c46a854402\'\n\'ot-tracer-sampled\', \'true\'\n\'ot-baggage-auth0-request-id\', \'8b8f630012aa4e2c4e692a80\'\n\'x-auth0-requestid\', \'85ce479a57d43747ed67\'\n\'access-control-allow-origin\', \'*\'\n\'access-control-allow-credentials\', \'false\'\n\'x-ratelimit-limit\', \'20\'\n\'x-ratelimit-remaining\', \'19\'\n\'x-ratelimit-reset\', \'1595469814\'\n\'cache-control\', \'public, max-age=15, stale-while-revalidate=15, stale-if-error=15\'\n\'etag\', \'W/\"c58-WlyAZ0fSEWSGQDEN8saHRcVzjpw\"\'\n\'x-cache-status\', \'EXPIRED\'\n\'x-envoy-upstream-service-time\', \'277\'

D0723 02:03:33.545 53 envoy] [53][client][external/envoy/source/common/http/codec_client.cc:105] [C4] response complete
D0723 02:03:33.545 53 envoy] [53][filter][external/envoy/source/extensions/filters/http/common/jwks_fetcher.cc:71] onSuccess: fetch pubkey [uri = https://<project-id>.auth0.com/.well-known/jwks.json]: success
D0723 02:03:33.545 53 envoy] [53][filter][external/envoy/source/extensions/filters/http/common/jwks_fetcher.cc:78] onSuccess: fetch pubkey [uri = https://<project-id>.auth0.com/.well-known/jwks.json]: succeeded
D0723 02:03:33.546 53 envoy] [53][jwt][external/envoy/source/extensions/filters/http/jwt_authn/authenticator.cc:267] auth0_jwk: JWT token verification completed with: OK
D0723 02:03:33.546 53 envoy] [53][jwt][external/envoy/source/extensions/filters/http/jwt_authn/filter.cc:87] Called Filter : check complete OK
D0723 02:03:33.546 53 envoy] [53][filter][src/envoy/http/service_control/filter.cc:46] Called ServiceControl Filter : decodeHeaders
D0723 02:03:33.546 53 envoy] [53][filter][src/envoy/http/service_control/service_control_call_impl.cc:182] Sending check : service_name: \"web-api-dot-<project-id>.appspot.com\"\noperation {\n  operation_id: \"a50ce11c-62fc-471c-8183-358ed0284212\"\n  operation_name: \"v1alpha.web_api_dot_project_id_appspot_com.Web_ListAccounts\"\n  consumer_id: \"api_key:<removed>\"\n  start_time {\n    seconds: 1595469813\n    nanos: 546096908\n  }\n  end_time {\n    seconds: 1595469813\n    nanos: 546096908\n  }\n  labels {\n    key: \"servicecontrol.googleapis.com/caller_ip\"\n    value: \"172.18.0.1\"\n  }\n  labels {\n    key: \"servicecontrol.googleapis.com/referer\"\n    value: \"http://localhost:8080/accounts/manage\"\n  }\n  labels {\n    key: \"servicecontrol.googleapis.com/service_agent\"\n    value: \"ESPv2/2.14.0\"\n  }\n  labels {\n    key: \"servicecontrol.googleapis.com/user_agent\"\n    value: \"ESPv2\"\n  }\n}\nservice_config_id: \"2020-07-16r1\"

D0723 02:03:33.546 53 envoy] [53][filter][src/envoy/http/service_control/http_call.cc:322] Service Control remote call: Check is created
D0723 02:03:33.546 53 envoy] [53][filter][src/envoy/http/service_control/http_call.cc:201] http call from [uri = https://servicecontrol.googleapis.com/v1/services/web-api-dot-<project-id>.appspot.com:check]: start
D0723 02:03:33.546 53 envoy] [53][router][external/envoy/source/common/router/router.cc:426] [C0][S312826532313055775] cluster \'service-control-cluster\' match for URL \'/v1/services/web-api-dot-<project-id>.appspot.com:check\'
D0723 02:03:33.546 53 envoy] [53][router][external/envoy/source/common/router/router.cc:583] [C0][S312826532313055775] router decoding headers:\n\':path\', \'/v1/services/web-api-dot-<project-id>.appspot.com:check\'\n\':authority\', \'servicecontrol.googleapis.com\'\n\':method\', \'POST\'\n\':scheme\', \'https\'\n\'content-length\', \'505\'\n\'authorization\', \'Bearer <removed>\'

D0723 02:03:33.546 53 envoy] [53][pool][external/envoy/source/common/http/conn_pool_base.cc:71] queueing request due to no available connections
D0723 02:03:33.546 53 envoy] [53][pool][external/envoy/source/common/conn_pool/conn_pool_base.cc:53] creating a new connection
D0723 02:03:33.546 53 envoy] [53][client][external/envoy/source/common/http/codec_client.cc:35] [C6] connecting
D0723 02:03:33.546 53 envoy] [53][connection][external/envoy/source/common/network/connection_impl.cc:753] [C6] connecting to 172.217.10.234:443
D0723 02:03:33.546 53 envoy] [53][connection][external/envoy/source/common/network/connection_impl.cc:769] [C6] connection in progress
D0723 02:03:33.546 53 envoy] [53][filter][src/envoy/http/service_control/filter.cc:64] Called ServiceControl filter : Stop
D0723 02:03:33.546 53 envoy] [53][pool][external/envoy/source/common/http/http1/conn_pool.cc:49] [C4] response complete
D0723 02:03:33.546 53 envoy] [53][pool][external/envoy/source/common/conn_pool/conn_pool_base.cc:98] [C4] destroying stream: 0 remaining
D0723 02:03:33.564 53 envoy] [53][connection][external/envoy/source/common/network/connection_impl.cc:616] [C6] connected
D0723 02:03:33.564 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C6] handshake expecting read
D0723 02:03:33.589 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C6] handshake expecting read
D0723 02:03:33.589 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C6] handshake expecting read
D0723 02:03:33.589 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C6] handshake expecting read
D0723 02:03:33.600 53 envoy] [53][connection][external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:176] [C6] handshake complete
D0723 02:03:33.600 53 envoy] [53][client][external/envoy/source/common/http/codec_client.cc:73] [C6] connected
D0723 02:03:33.600 53 envoy] [53][pool][external/envoy/source/common/conn_pool/conn_pool_base.cc:146] [C6] attaching to next request
D0723 02:03:33.600 53 envoy] [53][pool][external/envoy/source/common/conn_pool/conn_pool_base.cc:73] [C6] creating stream
D0723 02:03:33.600 53 envoy] [53][router][external/envoy/source/common/router/upstream_request.cc:342] [C0][S312826532313055775] pool ready
D0723 02:03:33.629 53 envoy] [53][router][external/envoy/source/common/router/router.cc:1153] [C0][S312826532313055775] upstream headers complete: end_stream=false
D0723 02:03:33.629 53 envoy] [53][http][external/envoy/source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=false):\n\':status\', \'401\'\n\'www-authenticate\', \'Bearer <removed>\'

D0723 02:03:33.629 53 envoy] [53][client][external/envoy/source/common/http/codec_client.cc:105] [C6] response complete
D0723 02:03:33.630 53 envoy] [53][filter][src/envoy/http/service_control/http_call.cc:101] http call response status code: 401, body: \010\020\022\320\001Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
E0723 02:03:33.630 53 envoy] [53][filter][src/envoy/http/service_control/client_cache.cc:144] Failed to call check, error: UNAUTHENTICATED:Calling Google Service Control API failed with: 401 and body: \010\020\022\320\001Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project., str body: \010\020\022\320\001Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
E0723 02:03:43.942451       6 rollout_id_change_detector.go:65] error occurred when checking new rollout id, fail to fetch new rollout id, http call to POST https://servicecontrol.googleapis.com/v1/services/web-api-dot-<project-id>.appspot.com:report returns not 200 OK: 403 Forbidden

I can open a new issue if this is unrelated - and I'd be happy to share my entire log privately if it helps any. I'm using the same ESPv2 startup options as mentioned earlier in this issue. It continues to work fine with ESPv2.7.0.

I should mention, the 401/403 error messages may be symptomatic of an error earlier in the stack. The following works fine with the same service account file so I'm pretty sure it has permissions:

curl -s \
    -H "Authorization: Bearer $(gcloud auth application-default print-access-token)" \
    -H "Content-Type: application/json" \
    https://servicecontrol.googleapis.com/v1/services/web-api-dot-<project-id>.appspot.com:check \
    --data '{
        "serviceConfigId": "2020-07-16r1", 
        operation: {
            "operationId": "<removed>",
            "consumerId":  "api_key:<removed>",
            "operationName": "<removed>",
            "startTime": "2020-07-22T22:01:23.045123456Z",
            "endTime": "2020-07-22T22:01:23.045123456Z",
        }
    }'

@nareddyt
Copy link
Contributor

This is unrelated, let me open a new issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants