Envoy only registers the admin port on server (re)boot

sulavvr commented 2 years ago

Title: Envoy setup as a systemd service doesn't seem to register the listeners, just registers the admin port.

Description: We seem to have an issue with Envoy not registering the listeners. We have envoy setup as a systemd service, and when the server starts/reboots, only the admin port is registered. The upstream is a Redis cluster.

envoy.service

[Unit]
Description=Envoy Proxy
Wants=network-online.target
Requires=network-online.target

[Service]
User=root
Group=root
Type=simple
ExecStart=/usr/bin/envoy -c /etc/envoy/config.yaml
Restart=on-failure
RestartSec=30s

[Install]
WantedBy=multi-user.target

config.yaml

admin:
address:
socket_address:
  address: 0.0.0.0
  port_value: 3000
static_resources:
listeners:
- name: redis_listener
address:
  socket_address:
    protocol: TCP
    address: 127.0.0.1
    port_value: 6380
filter_chains:
- filters:
  - name: envoy.filters.network.redis_proxy
    typed_config:
      "@type": type.googleapis.com/envoy.extensions.filters.network.redis_proxy.v3.RedisProxy
      stat_prefix: egress_redis
      settings:
        op_timeout: 3s
        read_policy: PREFER_MASTER
      prefix_routes:
        catch_all_route:
          cluster: redis_cluster
clusters:
- name: redis_cluster
connect_timeout: 2s
lb_policy: CLUSTER_PROVIDED
cluster_type:
  name: envoy.clusters.redis
  typed_config:
    '@type': type.googleapis.com/google.protobuf.Struct
    value:
      cluster_refresh_rate: 3600s
      cluster_refresh_timeout: 3s
      host_degraded_refresh_threshold: 1
outlier_detection:
  base_ejection_time: 30s
  consecutive_5xx: 1
  interval: 5s
upstream_connection_options:
  tcp_keepalive:
    keepalive_interval: 5
    keepalive_probes: 1
    keepalive_time: 30
load_assignment:
  cluster_name: redis_cluster
  endpoints:
  - lb_endpoints:
    - endpoint:
        address:
          socket_address:
            address: app.example.com
            port_value: 6379
typed_extension_protocol_options:
  envoy.filters.network.redis_proxy:
    '@type': type.googleapis.com/google.protobuf.Struct
    value:
      auth_password:
        inline_string: password
transport_socket:
  name: envoy.transport_sockets.tls
  typed_config:
    "@type": type.googleapis.com/envoy.extensions.transport_sockets.tls.v3.UpstreamTlsContext

Scanning the log, it seems fine overall.

Startup log

[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:385] initializing epoch 0 (base id=0, hot restart version=11.104)
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:387] statically linked extensions:
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.compression.decompressor: envoy.compression.brotli.decompressor, envoy.compression.gzip.decompressor
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.resource_monitors: envoy.resource_monitors.fixed_heap, envoy.resource_monitors.injected_resource
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.internal_redirect_predicates: envoy.internal_redirect_predicates.allow_listed_routes, envoy.internal_redirect_predicates.previous_routes, envoy.internal_redirect_predicates.safe_cross_scheme
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.http.cache: envoy.extensions.http.cache.simple
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.guarddog_actions: envoy.watchdog.abort_action, envoy.watchdog.profile_action
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.quic.proof_source: envoy.quic.proof_source.filter_chain
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.stats_sinks: envoy.dog_statsd, envoy.graphite_statsd, envoy.metrics_service, envoy.stat_sinks.dog_statsd, envoy.stat_sinks.graphite_statsd, envoy.stat_sinks.hystrix, envoy.stat_sinks.metrics_service, envoy.stat_sinks.statsd, envoy.stat_sinks.wasm, envoy.statsd
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.http.original_ip_detection: envoy.http.original_ip_detection.custom_header, envoy.http.original_ip_detection.xff
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.dubbo_proxy.serializers: dubbo.hessian2
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.upstreams: envoy.filters.connection_pools.tcp.generic
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.dubbo_proxy.route_matchers: default
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.dubbo_proxy.filters: envoy.filters.dubbo.router
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.wasm.runtime: envoy.wasm.runtime.null, envoy.wasm.runtime.v8
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.access_logger.extension_filters: envoy.access_loggers.extension_filters.cel
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.thrift_proxy.filters: envoy.filters.thrift.header_to_metadata, envoy.filters.thrift.rate_limit, envoy.filters.thrift.router
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.retry_priorities: envoy.retry_priorities.previous_priorities
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.tls.cert_validator: envoy.tls.cert_validator.default, envoy.tls.cert_validator.spiffe
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.common.key_value: envoy.key_value.file_based
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.matching.common_inputs: envoy.matching.common_inputs.environment_variable
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.matching.input_matchers: envoy.matching.matchers.consistent_hashing, envoy.matching.matchers.ip
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.filters.http: envoy.bandwidth_limit, envoy.buffer, envoy.cors, envoy.csrf, envoy.ext_authz, envoy.ext_proc, envoy.fault, envoy.filters.http.adaptive_concurrency, envoy.filters.http.admission_control, envoy.filters.http.alternate_protocols_cache, envoy.filters.http.aws_lambda, envoy.filters.http.aws_request_signing, envoy.filters.http.bandwidth_limit, envoy.filters.http.buffer, envoy.filters.http.cache, envoy.filters.http.cdn_loop, envoy.filters.http.composite, envoy.filters.http.compressor, envoy.filters.http.cors, envoy.filters.http.csrf, envoy.filters.http.decompressor, envoy.filters.http.dynamic_forward_proxy, envoy.filters.http.dynamo, envoy.filters.http.ext_authz, envoy.filters.http.ext_proc, envoy.filters.http.fault, envoy.filters.http.grpc_http1_bridge, envoy.filters.http.grpc_http1_reverse_bridge, envoy.filters.http.grpc_json_transcoder, envoy.filters.http.grpc_stats, envoy.filters.http.grpc_web, envoy.filters.http.header_to_metadata, envoy.filters.http.health_check, envoy.filters.http.ip_tagging, envoy.filters.http.jwt_authn, envoy.filters.http.local_ratelimit, envoy.filters.http.lua, envoy.filters.http.oauth2, envoy.filters.http.on_demand, envoy.filters.http.original_src, envoy.filters.http.ratelimit, envoy.filters.http.rbac, envoy.filters.http.router, envoy.filters.http.set_metadata, envoy.filters.http.stateful_session, envoy.filters.http.tap, envoy.filters.http.wasm, envoy.grpc_http1_bridge, envoy.grpc_json_transcoder, envoy.grpc_web, envoy.health_check, envoy.http_dynamo_filter, envoy.ip_tagging, envoy.local_rate_limit, envoy.lua, envoy.rate_limit, envoy.router, match-wrapper
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.bootstrap: envoy.bootstrap.wasm, envoy.extensions.network.socket_interface.default_socket_interface
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.dubbo_proxy.protocols: dubbo
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.compression.compressor: envoy.compression.brotli.compressor, envoy.compression.gzip.compressor
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.rbac.matchers: envoy.rbac.matchers.upstream_ip_port
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.request_id: envoy.request_id.uuid
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.filters.network: envoy.client_ssl_auth, envoy.echo, envoy.ext_authz, envoy.filters.network.client_ssl_auth, envoy.filters.network.connection_limit, envoy.filters.network.direct_response, envoy.filters.network.dubbo_proxy, envoy.filters.network.echo, envoy.filters.network.ext_authz, envoy.filters.network.http_connection_manager, envoy.filters.network.local_ratelimit, envoy.filters.network.mongo_proxy, envoy.filters.network.ratelimit, envoy.filters.network.rbac, envoy.filters.network.redis_proxy, envoy.filters.network.sni_cluster, envoy.filters.network.sni_dynamic_forward_proxy, envoy.filters.network.tcp_proxy, envoy.filters.network.thrift_proxy, envoy.filters.network.wasm, envoy.filters.network.zookeeper_proxy, envoy.http_connection_manager, envoy.mongo_proxy, envoy.ratelimit, envoy.redis_proxy, envoy.tcp_proxy
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.transport_sockets.downstream: envoy.transport_sockets.alts, envoy.transport_sockets.quic, envoy.transport_sockets.raw_buffer, envoy.transport_sockets.starttls, envoy.transport_sockets.tap, envoy.transport_sockets.tcp_stats, envoy.transport_sockets.tls, raw_buffer, starttls, tls
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.tracers: envoy.dynamic.ot, envoy.lightstep, envoy.tracers.datadog, envoy.tracers.dynamic_ot, envoy.tracers.lightstep, envoy.tracers.opencensus, envoy.tracers.skywalking, envoy.tracers.xray, envoy.tracers.zipkin, envoy.zipkin
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.transport_sockets.upstream: envoy.transport_sockets.alts, envoy.transport_sockets.quic, envoy.transport_sockets.raw_buffer, envoy.transport_sockets.starttls, envoy.transport_sockets.tap, envoy.transport_sockets.tcp_stats, envoy.transport_sockets.tls, envoy.transport_sockets.upstream_proxy_protocol, raw_buffer, starttls, tls
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.retry_host_predicates: envoy.retry_host_predicates.omit_canary_hosts, envoy.retry_host_predicates.omit_host_metadata, envoy.retry_host_predicates.previous_hosts
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.rate_limit_descriptors: envoy.rate_limit_descriptors.expr
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.access_loggers: envoy.access_loggers.file, envoy.access_loggers.http_grpc, envoy.access_loggers.open_telemetry, envoy.access_loggers.stderr, envoy.access_loggers.stdout, envoy.access_loggers.tcp_grpc, envoy.access_loggers.wasm, envoy.file_access_log, envoy.http_grpc_access_log, envoy.open_telemetry_access_log, envoy.stderr_access_log, envoy.stdout_access_log, envoy.tcp_grpc_access_log, envoy.wasm_access_log
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.http.stateful_header_formatters: preserve_case
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.filters.listener: envoy.filters.listener.http_inspector, envoy.filters.listener.original_dst, envoy.filters.listener.original_src, envoy.filters.listener.proxy_protocol, envoy.filters.listener.tls_inspector, envoy.listener.http_inspector, envoy.listener.original_dst, envoy.listener.original_src, envoy.listener.proxy_protocol, envoy.listener.tls_inspector
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.http.stateful_session: envoy.http.stateful_session.cookie
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.formatter: envoy.formatter.metadata, envoy.formatter.req_without_query
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.filters.udp_listener: envoy.filters.udp.dns_filter, envoy.filters.udp_listener.udp_proxy
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.resolvers: envoy.ip
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.quic.server.crypto_stream: envoy.quic.crypto_stream.server.quiche
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.upstream_options: envoy.extensions.upstreams.http.v3.HttpProtocolOptions, envoy.upstreams.http.http_protocol_options
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.network.dns_resolver: envoy.network.dns_resolver.cares
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.clusters: envoy.cluster.eds, envoy.cluster.logical_dns, envoy.cluster.original_dst, envoy.cluster.static, envoy.cluster.strict_dns, envoy.clusters.aggregate, envoy.clusters.dynamic_forward_proxy, envoy.clusters.redis
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.matching.action: composite-action, skip
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.thrift_proxy.transports: auto, framed, header, unframed
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.matching.http.input: request-headers, request-trailers, response-headers, response-trailers
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.health_checkers: envoy.health_checkers.redis
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.thrift_proxy.protocols: auto, binary, binary/non-strict, compact, twitter
[2022-03-31 17:13:06.595][696][info][main] [source/server/server.cc:389]   envoy.grpc_credentials: envoy.grpc_credentials.aws_iam, envoy.grpc_credentials.default, envoy.grpc_credentials.file_based_metadata
[2022-03-31 17:13:06.600][696][info][main] [source/server/server.cc:437] HTTP header map info:
[2022-03-31 17:13:06.601][696][info][main] [source/server/server.cc:440]   request header map: 656 bytes: :authority,:method,:path,:protocol,:scheme,accept,accept-encoding,access-control-request-headers,access-control-request-method,authentication,authorization,cache-control,cdn-loop,connection,content-encoding,content-length,content-type,expect,grpc-accept-encoding,grpc-timeout,if-match,if-modified-since,if-none-match,if-range,if-unmodified-since,keep-alive,origin,pragma,proxy-connection,proxy-status,referer,te,transfer-encoding,upgrade,user-agent,via,x-client-trace-id,x-envoy-attempt-count,x-envoy-decorator-operation,x-envoy-downstream-service-cluster,x-envoy-downstream-service-node,x-envoy-expected-rq-timeout-ms,x-envoy-external-address,x-envoy-force-trace,x-envoy-hedge-on-per-try-timeout,x-envoy-internal,x-envoy-ip-tags,x-envoy-max-retries,x-envoy-original-path,x-envoy-original-url,x-envoy-retriable-header-names,x-envoy-retriable-status-codes,x-envoy-retry-grpc-on,x-envoy-retry-on,x-envoy-upstream-alt-stat-name,x-envoy-upstream-rq-per-try-timeout-ms,x-envoy-upstream-rq-timeout-alt-response,x-envoy-upstream-rq-timeout-ms,x-envoy-upstream-stream-duration-ms,x-forwarded-client-cert,x-forwarded-for,x-forwarded-host,x-forwarded-proto,x-ot-span-context,x-request-id
[2022-03-31 17:13:06.601][696][info][main] [source/server/server.cc:440]   request trailer map: 128 bytes:
[2022-03-31 17:13:06.601][696][info][main] [source/server/server.cc:440]   response header map: 432 bytes: :status,access-control-allow-credentials,access-control-allow-headers,access-control-allow-methods,access-control-allow-origin,access-control-expose-headers,access-control-max-age,age,cache-control,connection,content-encoding,content-length,content-type,date,etag,expires,grpc-message,grpc-status,keep-alive,last-modified,location,proxy-connection,proxy-status,server,transfer-encoding,upgrade,vary,via,x-envoy-attempt-count,x-envoy-decorator-operation,x-envoy-degraded,x-envoy-immediate-health-check-fail,x-envoy-ratelimited,x-envoy-upstream-canary,x-envoy-upstream-healthchecked-cluster,x-envoy-upstream-service-time,x-request-id
[2022-03-31 17:13:06.601][696][info][main] [source/server/server.cc:440]   response trailer map: 152 bytes: grpc-message,grpc-status
[2022-03-31 17:13:06.603][696][info][main] [source/server/server.cc:780] runtime: {}
[2022-03-31 17:13:06.603][696][info][admin] [source/server/admin/admin.cc:134] admin address: 0.0.0.0:3000
[2022-03-31 17:13:06.603][696][info][config] [source/server/configuration_impl.cc:127] loading tracing configuration
[2022-03-31 17:13:06.603][696][info][config] [source/server/configuration_impl.cc:87] loading 0 static secret(s)
[2022-03-31 17:13:06.603][696][info][config] [source/server/configuration_impl.cc:93] loading 1 cluster(s)
[2022-03-31 17:13:06.607][696][info][config] [source/server/configuration_impl.cc:97] loading 1 listener(s)
[2022-03-31 17:13:06.609][696][info][config] [source/server/configuration_impl.cc:109] loading stats configuration
[2022-03-31 17:13:06.610][696][info][main] [source/server/server.cc:876] starting main dispatch loop

$ sudo lsof -i -P -n | grep envoy
envoy      696            root   20u  IPv4  18878      0t0  TCP *:3000 (LISTEN)

Also, if I just restart the envoy service, it works fine.

$ sudo systemctl restart envoy.service
$ sudo lsof -i -P -n | grep envoy
envoy     6003            root   20u  IPv4  97088      0t0  TCP *:3000 (LISTEN)
envoy     6003            root   22u  IPv4  97101      0t0  TCP 127.0.0.1:6380 (LISTEN)
envoy     6003            root   23u  IPv4  97102      0t0  TCP 127.0.0.1:6380 (LISTEN)

I tried a different port as well, but that didn't do much. I've also noticed that if I change the cluster_refresh_rate to the default value of 5 seconds instead of the 3600 seconds, then it works fine. But keeping it a higher value made sense because it should rarely change. Are we missing anything here? Any help would be appreciated. Thank you.

zhangbo1882 commented 2 years ago

I think you can set log level to get more debug information to see what happens.

ExecStart=/usr/bin/envoy -c /etc/envoy/config.yaml --log-level trace

sulavvr commented 2 years ago

Ahh yes, thanks @zhangbo1882! I probably could've done just that. :facepalm: Seems like it can't connect to Redis just yet.

[2022-04-02 02:32:01.184][707][debug][connection] [source/common/network/connection_impl.cc:907] [C0] connecting to 127.0.0.1:6379
[2022-04-02 02:32:01.185][707][debug][connection] [source/common/network/connection_impl.cc:927] [C0] connection in progress
[2022-04-02 02:32:01.185][707][trace][connection] [source/common/network/connection_impl.cc:478] [C0] writing 29 bytes, end_stream false
[2022-04-02 02:32:01.185][707][trace][connection] [source/common/network/connection_impl.cc:478] [C0] writing 28 bytes, end_stream false
[2022-04-02 02:32:01.185][707][trace][connection] [source/common/network/connection_impl.cc:563] [C0] socket event: 3
[2022-04-02 02:32:01.185][707][trace][connection] [source/common/network/connection_impl.cc:672] [C0] write ready
[2022-04-02 02:32:01.185][707][debug][connection] [source/common/network/connection_impl.cc:693] [C0] delayed connect error: 111
[2022-04-02 02:32:01.185][707][debug][connection] [source/common/network/connection_impl.cc:250] [C0] closing socket: 0
[2022-04-02 02:32:01.185][707][trace][connection] [source/common/network/connection_impl.cc:418] [C0] raising connection event 0
[2022-04-02 02:32:01.185][707][trace][main] [source/common/event/dispatcher_impl.cc:228] item added to deferred deletion list (size=1)
[2022-04-02 02:32:01.185][707][trace][main] [source/common/event/dispatcher_impl.cc:112] clearing deferred deletion list (size=1)
[2022-04-02 02:32:06.179][707][debug][main] [source/server/server.cc:246] flushing stats
[2022-04-02 02:32:06.179][707][debug][main] [source/server/server.cc:256] Envoy is not fully initialized, skipping histogram merge and flushing stats
[2022-04-02 02:32:11.182][707][debug][main] [source/server/server.cc:246] flushing stats
[2022-04-02 02:32:11.182][707][debug][main] [source/server/server.cc:256] Envoy is not fully initialized, skipping histogram merge and flushing stats
[2022-04-02 02:32:16.275][707][debug][main] [source/server/server.cc:246] flushing stats
[2022-04-02 02:32:16.277][707][debug][main] [source/server/server.cc:256] Envoy is not fully initialized, skipping histogram merge and flushing stats
[2022-04-02 02:32:21.346][707][debug][main] [source/server/server.cc:246] flushing stats
[2022-04-02 02:32:21.350][707][debug][main] [source/server/server.cc:256] Envoy is not fully initialized, skipping histogram merge and flushing stats
[2022-04-02 02:32:26.321][707][debug][main] [source/server/server.cc:246] flushing stats
[2022-04-02 02:32:26.325][707][debug][main] [source/server/server.cc:256] Envoy is not fully initialized, skipping histogram merge and flushing stats

envoyproxy / envoy

Envoy only registers the admin port on server (re)boot #20618