This repository was archived by the owner on Feb 16, 2019. It is now read-only.
This repository was archived by the owner on Feb 16, 2019. It is now read-only.
"404 NR 0 0 0" on deploys/updates #244
Description
Is this a BUG or FEATURE REQUEST?:
Did you review https://istio.io/help/ and existing issues to identify if this is already solved or being worked on?:
Yes
Bug:
Y
What Version of Istio and Kubernetes are you using, where did you get Istio from, Installation details
istioctl 0.5.0
kubectl 1.9
Is Istio Auth enabled or not ?
Auth Disabled
What happened:
When performing a deploy and rolling pods we get internal traffic that is unable to be routed and get 404 NR from the pods we're trying to contact
What you expected to happen:
To be able to contact the pods as normal
We're running istio 1.5.0 on GKE and I've noticed with version 1.5.0 (though it could be config) that when I perform a rolling deploy that other services are able to contact the new pods but receive the istio-proxy on the new pod states that the request is a 404 with NR (which I assume is no response?). Restarting the client pod (the other service) seems to fix this, no changes were made to the new pods.
In the istio-proxy sidecar I see logs like the following.. even though that endpoint does exist, the service itself doesn't seem to be being called at, as no zipkin trace is generated and no metrics are increased for that response code. Which would make sense, as even with a 404 a error response would have be sent back.
Here's our config for the sidecar..
Container ID: docker://46fe80184e8f7751edd99473aefe212032fbf7015259cb7b853087239365fc4f
Image: docker.io/istio/proxy:0.5.0
Image ID: docker-pullable://istio/proxy@sha256:3a9fc8a72faec478a7eca222bbb2ceec688514c95cf06ac12ab6235958c6883c
Port: <none>
Args:
proxy
sidecar
--configPath
/etc/istio/proxy
--binaryPath
/usr/local/bin/envoy
--serviceCluster
graphql
--drainDuration
2s
--parentShutdownDuration
3s
--discoveryAddress
istio-pilot.istio-system:15003
--discoveryRefreshDelay
1s
--zipkinAddress
zipkin:9411
--connectTimeout
1s
--statsdUdpAddress
istio-mixer.istio-system:9125
--proxyAdminPort
15000
--controlPlaneAuthPolicy
NONE
And here's what we see in the logs...
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.755088Z info Version root@2e4a18076b04-docker.io/istio-0.5.1-30acfe6528107ea333543309095659b93364b30d-Clean
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.755231Z info Proxy role: model.Node{Type:"sidecar", IPAddress:"10.20.1.205", ID:"practices-7854f4cc99-gdmkp.default", Domain:"default.svc.cluster.local"}
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.755279Z info Attempting to lookup address: istio-mixer.istio-system
practices-7854f4cc99-gdmkp istio-proxy {
practices-7854f4cc99-gdmkp istio-proxy "listeners": [],
practices-7854f4cc99-gdmkp istio-proxy "lds": {
practices-7854f4cc99-gdmkp istio-proxy "cluster": "lds",
practices-7854f4cc99-gdmkp istio-proxy "refresh_delay_ms": 10000
practices-7854f4cc99-gdmkp istio-proxy },
practices-7854f4cc99-gdmkp istio-proxy "admin": {
practices-7854f4cc99-gdmkp istio-proxy "access_log_path": "/dev/stdout",
practices-7854f4cc99-gdmkp istio-proxy "address": "tcp://127.0.0.1:15000"
practices-7854f4cc99-gdmkp istio-proxy },
practices-7854f4cc99-gdmkp istio-proxy "cluster_manager": {
practices-7854f4cc99-gdmkp istio-proxy "clusters": [
practices-7854f4cc99-gdmkp istio-proxy {
practices-7854f4cc99-gdmkp istio-proxy "name": "rds",
practices-7854f4cc99-gdmkp istio-proxy "connect_timeout_ms": 1000,
practices-7854f4cc99-gdmkp istio-proxy "type": "strict_dns",
practices-7854f4cc99-gdmkp istio-proxy "lb_type": "round_robin",
practices-7854f4cc99-gdmkp istio-proxy "hosts": [
practices-7854f4cc99-gdmkp istio-proxy {
practices-7854f4cc99-gdmkp istio-proxy "url": "tcp://istio-pilot.istio-system:15003"
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy ]
practices-7854f4cc99-gdmkp istio-proxy },
practices-7854f4cc99-gdmkp istio-proxy {
practices-7854f4cc99-gdmkp istio-proxy "name": "lds",
practices-7854f4cc99-gdmkp istio-proxy "connect_timeout_ms": 1000,
practices-7854f4cc99-gdmkp istio-proxy "type": "strict_dns",
practices-7854f4cc99-gdmkp istio-proxy "lb_type": "round_robin",
practices-7854f4cc99-gdmkp istio-proxy "hosts": [
practices-7854f4cc99-gdmkp istio-proxy {
practices-7854f4cc99-gdmkp istio-proxy "url": "tcp://istio-pilot.istio-system:15003"
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy ]
practices-7854f4cc99-gdmkp istio-proxy },
practices-7854f4cc99-gdmkp istio-proxy {
practices-7854f4cc99-gdmkp istio-proxy "name": "zipkin",
practices-7854f4cc99-gdmkp istio-proxy "connect_timeout_ms": 1000,
practices-7854f4cc99-gdmkp istio-proxy "type": "strict_dns",
practices-7854f4cc99-gdmkp istio-proxy "lb_type": "round_robin",
practices-7854f4cc99-gdmkp istio-proxy "hosts": [
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.760802Z info Addr resolved to: 10.23.253.60:9125
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.760952Z info Finished lookup of address: istio-mixer.istio-system
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.761661Z info Effective config: binaryPath: /usr/local/bin/envoy
practices-7854f4cc99-gdmkp istio-proxy configPath: /etc/istio/proxy
practices-7854f4cc99-gdmkp istio-proxy connectTimeout: 1.000s
practices-7854f4cc99-gdmkp istio-proxy discoveryAddress: istio-pilot.istio-system:15003
practices-7854f4cc99-gdmkp istio-proxy discoveryRefreshDelay: 1.000s
practices-7854f4cc99-gdmkp istio-proxy drainDuration: 2.000s
practices-7854f4cc99-gdmkp istio-proxy parentShutdownDuration: 3.000s
practices-7854f4cc99-gdmkp istio-proxy proxyAdminPort: 15000
practices-7854f4cc99-gdmkp istio-proxy serviceCluster: practices
practices-7854f4cc99-gdmkp istio-proxy statsdUdpAddress: 10.23.253.60:9125
practices-7854f4cc99-gdmkp istio-proxy zipkinAddress: zipkin.default:9411
practices-7854f4cc99-gdmkp istio-proxy
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.761695Z info Monitored certs: []envoy.CertSource{}
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.761822Z info Starting proxy agent
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.761885Z info Received new config, resetting budget
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.761906Z info Reconciling configuration (budget 10)
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.761953Z info Epoch 0 starting
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.761999Z info writing configuration to /etc/istio/proxy/envoy-rev0.json
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.762266Z info Availability zone not set, proxy will default to not using zone aware routing. To manually override use the --availabilityZone flag.
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:08:49.762705Z info Envoy command: [-c /etc/istio/proxy/envoy-rev0.json --restart-epoch 0 --drain-time-s 2 --parent-shutdown-time-s 3 --service-cluster practices --service-node sidecar~10.20.1.205~practices-7854f4cc99-gdmkp.default~default.svc.cluster.local --max-obj-name-len 189 -l off]
practices-7854f4cc99-gdmkp istio-proxy {
practices-7854f4cc99-gdmkp istio-proxy "url": "tcp://zipkin.default:9411"
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy ]
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy ],
practices-7854f4cc99-gdmkp istio-proxy "sds": {
practices-7854f4cc99-gdmkp istio-proxy "cluster": {
practices-7854f4cc99-gdmkp istio-proxy "name": "sds",
practices-7854f4cc99-gdmkp istio-proxy "connect_timeout_ms": 1000,
practices-7854f4cc99-gdmkp istio-proxy "type": "strict_dns",
practices-7854f4cc99-gdmkp istio-proxy "lb_type": "round_robin",
practices-7854f4cc99-gdmkp istio-proxy "hosts": [
practices-7854f4cc99-gdmkp istio-proxy {
practices-7854f4cc99-gdmkp istio-proxy "url": "tcp://istio-pilot.istio-system:15003"
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy ]
practices-7854f4cc99-gdmkp istio-proxy },
practices-7854f4cc99-gdmkp istio-proxy "refresh_delay_ms": 10000
practices-7854f4cc99-gdmkp istio-proxy },
practices-7854f4cc99-gdmkp istio-proxy "cds": {
practices-7854f4cc99-gdmkp istio-proxy "cluster": {
practices-7854f4cc99-gdmkp istio-proxy "name": "cds",
practices-7854f4cc99-gdmkp istio-proxy "connect_timeout_ms": 1000,
practices-7854f4cc99-gdmkp istio-proxy "type": "strict_dns",
practices-7854f4cc99-gdmkp istio-proxy "lb_type": "round_robin",
practices-7854f4cc99-gdmkp istio-proxy "hosts": [
practices-7854f4cc99-gdmkp istio-proxy {
practices-7854f4cc99-gdmkp istio-proxy "url": "tcp://istio-pilot.istio-system:15003"
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy ]
practices-7854f4cc99-gdmkp istio-proxy },
practices-7854f4cc99-gdmkp istio-proxy "refresh_delay_ms": 10000
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy },
practices-7854f4cc99-gdmkp istio-proxy "statsd_udp_ip_address": "10.23.253.60:9125",
practices-7854f4cc99-gdmkp istio-proxy "tracing": {
practices-7854f4cc99-gdmkp istio-proxy "http": {
practices-7854f4cc99-gdmkp istio-proxy "driver": {
practices-7854f4cc99-gdmkp istio-proxy "type": "zipkin",
practices-7854f4cc99-gdmkp istio-proxy "config": {
practices-7854f4cc99-gdmkp istio-proxy "collector_cluster": "zipkin",
practices-7854f4cc99-gdmkp istio-proxy "collector_endpoint": "/api/v1/spans"
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy }
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:09:07.612Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "097c9ddb-55d3-92a5-aa17-0d3a074c67e1" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:09:09.542Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-node/1.8.0 grpc-c/5.0.0 (linux; chttp2; generous)" "3289bb8c-90cb-9242-99ce-6deda7e1865e" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:09:10.838Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "48480cc5-5a9e-95d7-8a0c-6c908b54e2de" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy }[libprotobuf INFO external/mixerclient_git/src/check_cache.cc:155] Add a new Referenced for check cache: Absence-keys: Exact-keys: context.protocol, destination.service,
practices-7854f4cc99-gdmkp istio-proxy 2018-03-19T12:09:19.766904Z info Proxy availability zone: europe-west2/europe-west2-a
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:09:25.475Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "e220faa8-3906-949f-97dd-86e50eee5cfd" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:09:25.501Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "37195340-e4ba-90e7-b950-bae919a8e817" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:09:38.345Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "22c72547-1e88-9014-92dd-8d83fd3ba2ae" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:10:05.330Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "99188805-9ff3-9e8e-897e-32123906b1d0" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:10:09.332Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "cc86ef64-ad0b-9c72-9dae-c781121a9d8c" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:10:14.807Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "2261ecb0-b6a4-9db6-8ad8-815a51e0ff8c" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:10:18.844Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "e2235cc7-9903-93e7-945e-422757cbe4ac" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:10:22.444Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "cd747200-bb49-9d27-86e3-8e8f81c8b37a" "practices:80" "-"
practices-7854f4cc99-gdmkp istio-proxy [2018-03-19T12:10:22.548Z] "POST /practices.Practices/Get HTTP/2" 404 NR 0 0 0 - "-" "grpc-go/1.9.1" "ea5186e4-5459-9c73-aeff-d6affb1a9690" "practices:80" "-"`
Unfortunately what happens is that our other apps start receiving a lot of NotFounds which is very hard to detect as a failure..
Restarting the pod (perhaps more than once) will eventually get it working back to normal without any config changes.
This may be related to #221