Uploaded image for project: 'Knative Serving'
  1. Knative Serving
  2. SRVKS-207

scaling from zero, istio-proxy takes too long to become ready sometimes (maistra 0.12+multitenant+cni)

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Critical Critical
    • TP1
    • v0.7.0
    • None
    • None
    • Serverless Sprint 171, Serverless Sprint 172

      Deploying the autoscaler sample https://github.com/knative/docs/blob/master/docs/serving/samples/autoscale-go/service.yaml

      on knative serving 0.7.1 on OCP 4.1.9 with Maistra 0.12 with multitenancy with CNI

      starting the deployment with a small load, e.g.

      ~/go/bin/hey -c 1 -n 100 'http://autoscale-go.myproject.apps.example.com/?sleep=100&prime=10000&bloat=5'

      sometimes, the application pod is not becoming ready for several minutes (containers with unready status: [queue-proxy istio-proxy] )

      oc logs autoscale-go-qgbqm-deployment-5d8b88579f-24nqm -c istio-proxy
2019-08-09T12:16:01.460157Z	info	FLAG: --applicationPorts="[8080,8022,9090,9091,8012]"
2019-08-09T12:16:01.460196Z	info	FLAG: --binaryPath="/usr/local/bin/envoy"
2019-08-09T12:16:01.460205Z	info	FLAG: --concurrency="2"
2019-08-09T12:16:01.460211Z	info	FLAG: --configPath="/etc/istio/proxy"
2019-08-09T12:16:01.460219Z	info	FLAG: --connectTimeout="10s"
2019-08-09T12:16:01.460225Z	info	FLAG: --controlPlaneAuthPolicy="NONE"
2019-08-09T12:16:01.460232Z	info	FLAG: --controlPlaneBootstrap="true"
2019-08-09T12:16:01.460237Z	info	FLAG: --customConfigFile=""
2019-08-09T12:16:01.460243Z	info	FLAG: --datadogAgentAddress=""
2019-08-09T12:16:01.460249Z	info	FLAG: --disableInternalTelemetry="false"
2019-08-09T12:16:01.460256Z	info	FLAG: --discoveryAddress="istio-pilot.istio-system:15010"
2019-08-09T12:16:01.460262Z	info	FLAG: --domain="myproject.svc.cluster.local"
2019-08-09T12:16:01.460268Z	info	FLAG: --drainDuration="45s"
2019-08-09T12:16:01.460273Z	info	FLAG: --envoyMetricsServiceAddress=""
2019-08-09T12:16:01.460279Z	info	FLAG: --help="false"
2019-08-09T12:16:01.460284Z	info	FLAG: --id=""
2019-08-09T12:16:01.460290Z	info	FLAG: --ip=""
2019-08-09T12:16:01.460295Z	info	FLAG: --lightstepAccessToken=""
2019-08-09T12:16:01.460301Z	info	FLAG: --lightstepAddress=""
2019-08-09T12:16:01.460307Z	info	FLAG: --lightstepCacertPath=""
2019-08-09T12:16:01.460312Z	info	FLAG: --lightstepSecure="false"
2019-08-09T12:16:01.460318Z	info	FLAG: --log_as_json="false"
2019-08-09T12:16:01.460323Z	info	FLAG: --log_caller=""
2019-08-09T12:16:01.460329Z	info	FLAG: --log_output_level="default:info"
2019-08-09T12:16:01.460334Z	info	FLAG: --log_rotate=""
2019-08-09T12:16:01.460340Z	info	FLAG: --log_rotate_max_age="30"
2019-08-09T12:16:01.460345Z	info	FLAG: --log_rotate_max_backups="1000"
2019-08-09T12:16:01.460351Z	info	FLAG: --log_rotate_max_size="104857600"
2019-08-09T12:16:01.460357Z	info	FLAG: --log_stacktrace_level="default:none"
2019-08-09T12:16:01.460367Z	info	FLAG: --log_target="[stdout]"
2019-08-09T12:16:01.460374Z	info	FLAG: --parentShutdownDuration="1m0s"
2019-08-09T12:16:01.460381Z	info	FLAG: --proxyAdminPort="15000"
2019-08-09T12:16:01.460387Z	info	FLAG: --proxyLogLevel="warning"
2019-08-09T12:16:01.460394Z	info	FLAG: --serviceCluster="autoscale-go-qgbqm.myproject"
2019-08-09T12:16:01.460401Z	info	FLAG: --serviceregistry="Kubernetes"
2019-08-09T12:16:01.460407Z	info	FLAG: --statsdUdpAddress=""
2019-08-09T12:16:01.460413Z	info	FLAG: --statusPort="15020"
2019-08-09T12:16:01.460418Z	info	FLAG: --templateFile=""
2019-08-09T12:16:01.460425Z	info	FLAG: --trust-domain=""
2019-08-09T12:16:01.460432Z	info	FLAG: --zipkinAddress="zipkin.istio-system:9411"
2019-08-09T12:16:01.460455Z	info	Version redhat@redhat-brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift-istio-tech-preview-0.12.0-2-7b77ae81a3f95cf0d0b7d30bbcacc8d151786d2d-Clean
2019-08-09T12:16:01.460584Z	info	Obtained private IP [10.128.4.45 fe80::4870:e1ff:fe28:f5df]
2019-08-09T12:16:01.460642Z	info	Proxy role: &model.Proxy{ClusterID:"", Type:"sidecar", IPAddresses:[]string{"10.128.4.45", "10.128.4.45", "fe80::4870:e1ff:fe28:f5df"}, ID:"autoscale-go-qgbqm-deployment-5d8b88579f-24nqm.myproject", Locality:(*core.Locality)(nil), DNSDomain:"myproject.svc.cluster.local", ConfigNamespace:"", TrustDomain:"cluster.local", Metadata:map[string]string{}, SidecarScope:(*model.SidecarScope)(nil), ServiceInstances:[]*model.ServiceInstance(nil), WorkloadLabels:model.LabelsCollection(nil)}
2019-08-09T12:16:01.460667Z	info	PilotSAN []string(nil)
2019-08-09T12:16:01.460987Z	info	Effective config: binaryPath: /usr/local/bin/envoy
concurrency: 2
configPath: /etc/istio/proxy
connectTimeout: 10s
discoveryAddress: istio-pilot.istio-system:15010
drainDuration: 45s
parentShutdownDuration: 60s
proxyAdminPort: 15000
serviceCluster: autoscale-go-qgbqm.myproject
statNameLength: 189
tracing:
  zipkin:
    address: zipkin.istio-system:9411

2019-08-09T12:16:01.461012Z	info	Monitored certs: []string{"/etc/certs/cert-chain.pem", "/etc/certs/key.pem", "/etc/certs/root-cert.pem"}
2019-08-09T12:16:01.461027Z	info	PilotSAN []string(nil)
2019-08-09T12:16:01.461226Z	info	Starting proxy agent
2019-08-09T12:16:01.461304Z	info	Opening status port 15020

2019-08-09T12:16:01.461648Z	info	Received new config, resetting budget
2019-08-09T12:16:01.461665Z	info	Reconciling retry (budget 10)
2019-08-09T12:16:01.461691Z	info	Epoch 0 starting
2019-08-09T12:16:01.461785Z	info	watching /etc/certs for changes
2019-08-09T12:16:01.462396Z	info	Envoy command: [-c /etc/istio/proxy/envoy-rev0.json --restart-epoch 0 --drain-time-s 45 --parent-shutdown-time-s 60 --service-cluster autoscale-go-qgbqm.myproject --service-node sidecar~10.128.4.45~autoscale-go-qgbqm-deployment-5d8b88579f-24nqm.myproject~myproject.svc.cluster.local --max-obj-name-len 189 --allow-unknown-fields -l warning --concurrency 2]
[2019-08-09 12:16:01.484][18][warning][misc] [external/envoy/source/common/protobuf/utility.cc:174] Using deprecated option 'envoy.api.v2.Cluster.hosts' from file cds.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
[2019-08-09 12:16:01.484][18][warning][misc] [external/envoy/source/common/protobuf/utility.cc:174] Using deprecated option 'envoy.api.v2.Cluster.hosts' from file cds.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
[2019-08-09 12:16:01.484][18][warning][misc] [external/envoy/source/common/protobuf/utility.cc:174] Using deprecated option 'envoy.api.v2.Cluster.hosts' from file cds.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
[2019-08-09 12:16:01.488][18][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 14, no healthy upstream
[2019-08-09 12:16:01.488][18][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:49] Unable to establish new stream
[2019-08-09 12:16:01.888][18][warning][misc] [external/envoy/source/common/protobuf/utility.cc:174] Using deprecated option 'envoy.api.v2.Listener.use_original_dst' from file lds.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
2019-08-09T12:16:02.287681Z	info	watchFileEvents: "/etc/certs": MODIFY|ATTRIB
2019-08-09T12:16:02.287756Z	info	watchFileEvents: "/etc/certs/..2019_08_09_12_15_53.597335779": MODIFY|ATTRIB
2019-08-09T12:16:03.285317Z	info	watchFileEvents: "/etc/certs": MODIFY|ATTRIB
2019-08-09T12:16:03.285425Z	info	watchFileEvents: "/etc/certs/..2019_08_09_12_15_53.597335779": MODIFY|ATTRIB
2019-08-09T12:16:03.491754Z	info	Envoy proxy is NOT ready: 6 errors occurred:

* failed checking application ports. listeners="0.0.0.0:15090","172.30.199.220:9091","172.30.67.42:9090","172.30.251.23:42422","172.30.131.205:443","172.30.176.58:9090","172.30.254.116:15020","172.30.51.133:9090","172.30.63.64:443","172.30.246.52:443","172.30.254.116:443","172.30.75.123:9091","172.30.67.42:9091","172.30.78.213:15011","172.30.59.166:15443","172.30.40.141:443","172.30.199.220:9090","172.30.19.166:9091","172.30.189.95:9091","172.30.40.141:15443","172.30.189.95:9090","172.30.40.141:15020","172.30.75.123:9090","172.30.113.6:9091","172.30.237.139:9090","172.30.59.166:443","172.30.176.58:443","172.30.19.166:9090","172.30.113.6:9090","0.0.0.0:9090","0.0.0.0:80","0.0.0.0:8060","0.0.0.0:9901","0.0.0.0:9091","0.0.0.0:15010","0.0.0.0:8080","0.0.0.0:15004","0.0.0.0:81","0.0.0.0:15014","0.0.0.0:15001"
* envoy missing listener for inbound application port: 8080
* envoy missing listener for inbound application port: 8022
* envoy missing listener for inbound application port: 9090
* envoy missing listener for inbound application port: 9091
* envoy missing listener for inbound application port: 8012
2019-08-09T12:16:05.490908Z	info	Envoy proxy is NOT ready: 6 errors occurred:

* failed checking application ports. listeners="0.0.0.0:15090","172.30.199.220:9091","172.30.67.42:9090","172.30.251.23:42422","172.30.131.205:443","172.30.176.58:9090","172.30.254.116:15020","172.30.51.133:9090","172.30.63.64:443","172.30.246.52:443","172.30.254.116:443","172.30.75.123:9091","172.30.67.42:9091","172.30.78.213:15011","172.30.59.166:15443","172.30.40.141:443","172.30.199.220:9090","172.30.19.166:9091","172.30.189.95:9091","172.30.40.141:15443","172.30.189.95:9090","172.30.40.141:15020","172.30.75.123:9090","172.30.113.6:9091","172.30.237.139:9090","172.30.59.166:443","172.30.176.58:443","172.30.19.166:9090","172.30.113.6:9090","0.0.0.0:9090","0.0.0.0:80","0.0.0.0:8060","0.0.0.0:9901","0.0.0.0:9091","0.0.0.0:15010","0.0.0.0:8080","0.0.0.0:15004","0.0.0.0:81","0.0.0.0:15014","0.0.0.0:15001"
* envoy missing listener for inbound application port: 8080
* envoy missing listener for inbound application port: 8022
* envoy missing listener for inbound application port: 9090
* envoy missing listener for inbound application port: 9091
* envoy missing listener for inbound application port: 8012
2019-08-09T12:16:07.491259Z	info	Envoy proxy is NOT ready: 6 errors occurred:

* failed checking application ports. listeners="0.0.0.0:15090","172.30.199.220:9091","172.30.67.42:9090","172.30.251.23:42422","172.30.131.205:443","172.30.176.58:9090","172.30.254.116:15020","172.30.51.133:9090","172.30.63.64:443","172.30.246.52:443","172.30.254.116:443","172.30.75.123:9091","172.30.67.42:9091","172.30.78.213:15011","172.30.59.166:15443","172.30.40.141:443","172.30.199.220:9090","172.30.19.166:9091","172.30.189.95:9091","172.30.40.141:15443","172.30.189.95:9090","172.30.40.141:15020","172.30.75.123:9090","172.30.113.6:9091","172.30.237.139:9090","172.30.59.166:443","172.30.176.58:443","172.30.19.166:9090","172.30.113.6:9090","0.0.0.0:9090","0.0.0.0:80","0.0.0.0:8060","0.0.0.0:9901","0.0.0.0:9091","0.0.0.0:15010","0.0.0.0:8080","0.0.0.0:15004","0.0.0.0:81","0.0.0.0:15014","0.0.0.0:15001"
* envoy missing listener for inbound application port: 8080
* envoy missing listener for inbound application port: 8022
* envoy missing listener for inbound application port: 9090
* envoy missing listener for inbound application port: 9091
* envoy missing listener for inbound application port: 8012
2019-08-09T12:16:09.490824Z	info	Envoy proxy is NOT ready: 6 errors occurred:

... (repeats)

        1. SRVKS-207-maschmid-logs.tar.bz2
          1.33 MB
        2. SRVKS-207_reproducer.sh
          1 kB

              Unassigned Unassigned
              maschmid@redhat.com Marek Schmidt
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

                Created:
                Updated:
                Resolved: