503s plagging the tests and will affect customers too

[ldemailly]

@kyessenov says there is a known issue with ingress generating random 503s:

"
related to incoherent RDS/LDS I think
RDS/LDS might be racing
it's racing every second
start ingress, make lots of requests
you'll see 503s, very easy to replicate
"

clearly we can't ship something that would generate spurious errors every second

[ldemailly]

example of where it happens (but it's all over and apparently has been all over for a long time):

https://k8s-gubernator.appspot.com/build/istio-prow/pull/istio_istio/647/e2e-suite-no_rbac-no_auth/224/

W0902 21:55:39.766] 21:55:39 I httprunner.go:75> Starting http test for http://10.142.0.13:32697/productpage with 8 threads at 100.0 qps
W0902 21:55:53.114] 21:55:53 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:55:59.120] 21:55:59 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:55:59.349] 21:55:59 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:03.260] 21:56:03 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:09.055] 21:56:09 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:10.916] 21:56:10 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:17.879] 21:56:17 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:18.484] 21:56:18 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:20.400] 21:56:20 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:21.173] 21:56:21 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:24.506] 21:56:24 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:27.667] 21:56:27 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:28.614] 21:56:28 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:29.355] 21:56:29 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:35.548] 21:56:35 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:35.968] 21:56:35 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:36.440] 21:56:36 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:41.148] 21:56:41 W http.go:533> Parsed non ok code 503 (HTTP/1.1 503)
W0902 21:56:42.630] I0902 21:56:42.627691     891 mixer_test.go:326] Summary: 2512 reqs (2494 200s, 0 400s)
I0902 21:56:42.730] Ended after 1m0.173911765s : 2512 calls. qps=41.746
I0902 21:56:42.731] Aggregated Function Time : count 2512 avg 0.1913638 +/- 0.1068 min 0.074864405 max 5.164101853 sum 480.705869
I0902 21:56:42.731] # range, mid point, percentile, count
I0902 21:56:42.731] >= 0.07 < 0.08 , 0.075 , 0.16, 4
I0902 21:56:42.731] >= 0.08 < 0.09 , 0.085 , 0.40, 6
I0902 21:56:42.731] >= 0.09 < 0.1 , 0.095 , 0.56, 4
I0902 21:56:42.731] >= 0.1 < 0.12 , 0.11 , 1.19, 16
I0902 21:56:42.731] >= 0.12 < 0.14 , 0.13 , 8.56, 185
I0902 21:56:42.731] >= 0.14 < 0.16 , 0.15 , 23.49, 375
I0902 21:56:42.732] >= 0.16 < 0.18 , 0.17 , 43.55, 504
I0902 21:56:42.732] >= 0.18 < 0.2 , 0.19 , 64.61, 529
I0902 21:56:42.732] >= 0.2 < 0.25 , 0.225 , 92.24, 694
I0902 21:56:42.732] >= 0.25 < 0.3 , 0.275 , 98.85, 166
I0902 21:56:42.732] >= 0.3 < 0.35 , 0.325 , 99.80, 24
I0902 21:56:42.732] >= 0.35 < 0.4 , 0.375 , 99.96, 4
I0902 21:56:42.732] >= 5 < 7.5 , 6.25 , 100.00, 1
I0902 21:56:42.732] # target 90% 0.245951
I0902 21:56:42.732] Code 200 : 2494
I0902 21:56:42.732] Code 503 : 18

so a typical simple test seems to get 0.7% of errors (after warmup etc)

and some time it seems 100% 503s for a long time (maybe a different warm up/bring up problem:)

W0902 21:58:22.869] I0902 21:58:22.868328    1598 demo_test.go:258] Waiting for rules to propagate...
W0902 21:58:53.113] I0902 21:58:53.112105    1598 demo_test.go:148] Get from page: 503
W0902 21:58:53.113] E0902 21:58:53.112144    1598 demo_test.go:159] Couldn't get to the bookinfo product page, trying again in 5 second
W0902 21:58:58.252] I0902 21:58:58.251599    1598 demo_test.go:148] Get from page: 503
W0902 21:58:58.253] E0902 21:58:58.251637    1598 demo_test.go:159] Couldn't get to the bookinfo product page, trying again in 10 second
W0902 21:59:08.394] I0902 21:59:08.392467    1598 demo_test.go:148] Get from page: 503
W0902 21:59:08.395] E0902 21:59:08.392503    1598 demo_test.go:159] Couldn't get to the bookinfo product page, trying again in 15 second
W0902 21:59:23.534] I0902 21:59:23.532957    1598 demo_test.go:148] Get from page: 503
W0902 21:59:23.534] E0902 21:59:23.532983    1598 demo_test.go:159] Couldn't get to the bookinfo product page, trying again in 20 second
W0902 21:59:43.675] I0902 21:59:43.674150    1598 demo_test.go:148] Get from page: 503
W0902 21:59:43.675] E0902 21:59:43.674185    1598 demo_test.go:159] Couldn't get to the bookinfo product page, trying again in 25 second
W0902 22:00:08.817] I0902 22:00:08.815778    1598 demo_test.go:148] Get from page: 503
W0902 22:00:08.817] E0902 22:00:08.815824    1598 framework.go:199] Failed to complete Init. Error unable to set default route

[ldemailly]

I think the spurious small % and the block of 503s are different problems but both are critical

example of broken block:
https://k8s-gubernator.appspot.com/build/istio-prow/pull/istio_pilot/1172/pilot-e2e-smoketest/269/
(saved to https://gist.github.com/ldemailly/3389eeb217ad6433702a30b7638bcb92 in case the build log disappears)

[mandarjog]

W0904 22:50:01.009] I0904 22:50:01.008143    1057 kubeUtils.go:198] Istio ingress: 10.142.0.3:32605

I0904 22:50:41.116] === RUN   TestGlobalCheckAndReport
W0904 22:50:41.216] I0904 22:50:41.106686    1057 framework.go:147] Initialization complete
W0904 22:50:41.216] I0904 22:50:41.106718    1057 framework.go:202] Running test
W0904 22:50:41.459] I0904 22:50:41.458584    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)
W0904 22:50:44.534] I0904 22:50:44.533302    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)
W0904 22:50:47.647] I0904 22:50:47.646442    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)
W0904 22:50:50.724] I0904 22:50:50.723032    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)
W0904 22:50:53.799] I0904 22:50:53.798334    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)
W0904 22:50:56.871] I0904 22:50:56.870806    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)
W0904 22:50:59.965] I0904 22:50:59.964719    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)
W0904 22:51:03.041] I0904 22:51:03.040306    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)
W0904 22:51:06.121] I0904 22:51:06.119853    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)
W0904 22:51:09.199] I0904 22:51:09.197200    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)
W0904 22:51:12.270] I0904 22:51:12.268739    1057 mixer_test.go:483] Get from http://10.142.0.3:32605/productpage: 503 Service Unavailable (503)

[sdake]

@ldemailly @gnirodi

I've spent ~40 hours bringing up Istio without reproducible success. I did have the bookinfo sample operational for a short period, however, over the last couple of weeks I've become completely blocked. Here is my debug information in case someone finds it useful. I will continue debugging - any advice would be of help to fix the problem.

My environment:

Dual Xeon 256g ram AIO deployment
Centos 7.3 minimal installation with full yum update
go 1.8.3 from Red Hat Koji
firewalld disabled
selinux disabled
self-built istioctl from 3b31d818a1804e8d85e3396ed0f844c0893e2469
Kubernetes 1.7.5 from upstream RPMs
run as user "sdake" (not root)

I run the following initialization script:

sudo sed -i 's/10.96.0.10/10.3.3.10/g' /etc/systemd/system/kubelet.service.d/10-kubeadm.conf
sudo systemctl daemon-reload
sudo systemctl stop kubelet
sudo systemctl enable kubelet
sudo systemctl start kubelet
sudo kubeadm init --pod-network-cidr=10.1.0.0/16 --service-cidr=10.3.3.0/24
mkdir -p $HOME/.kube
sudo -H cp /etc/kubernetes/admin.conf $HOME/.kube/config
sudo -H chown $(id -u):$(id -g) $HOME/.kube/config
kubectl taint nodes --all=true  node-role.kubernetes.io/master:NoSchedule-
kubectl apply -f calico.yaml

# Deploy Istio
kubectl apply -f install/kubernetes/istio-rbac-beta.yaml
kubectl apply -f install/kubernetes/istio.yaml
kubectl apply -f install/kubernetes/addons/prometheus.yaml
kubectl apply -f install/kubernetes/addons/grafana.yaml
kubectl apply -f install/kubernetes/addons/servicegraph.yaml
kubectl apply -f install/kubernetes/addons/zipkin.yaml
echo "Horizontal or Vertical?"`

NB: I have run these commands manually verifying each operation completes before continuing further.

My calico.yaml has been modified to match the above kubeadm network operations.
https://paste.fedoraproject.org/paste/lWxMwGV95S1417IiXeg1IQ/

Everything comes up and enters the RUNNING state. CNI+httpbin has been verified to work by:

[sdake@falkor-01 istio]$ kubectl apply -f samples/apps/httpbin/httpbin.yaml
service "httpbin" created
deployment "httpbin" created`
[sdake@falkor-01 istio]$ kubectl apply -f samples/apps/sleep/sleep.yaml 
service "sleep" created
deployment "sleep" created
[sdake@falkor-01 istio]$ kubectl get pods | grep sleep
sleep-3432132412-qfk7b            1/1       Running   0          21s
[sdake@falkor-01 istio]$ kubectl exec -it sleep-3432132412-qfk7b bash
httpbin-3158034148-x5wj7          1/1       Running   0          3m        192.168.89.128   falkor-01
[sdake@falkor-01 ~]$ kubectl get pod -o wide | grep httpbin
[sdake@falkor-01 istio]$ kubectl exec -it sleep-3432132412-qfk7b bash
root@sleep-3432132412-qfk7b:/# curl httpbin:8000/headers
{
  "headers": {
    "Accept": "*/*", 
    "Host": "httpbin:8000", 
    "User-Agent": "curl/7.35.0"
  }
}

root@httpbin-3158034148-x5wj7:/# ps -ef
UID        PID  PPID  C STIME TTY          TIME CMD
root         1     0  0 22:09 ?        00:00:00 /usr/bin/python3 /usr/local/bin/gunicorn --bind=0.0.0.0:8000 httpbin:app
root        10     1  0 22:09 ?        00:00:00 /usr/bin/python3 /usr/local/bin/gunicorn --bind=0.0.0.0:8000 httpbin:app
root        12     0  0 22:25 ?        00:00:00 bash
root        27    12  0 22:25 ?        00:00:00 ps -ef

I took a look at the IP tables rules:

# Generated by iptables-save v1.4.21 on Thu Sep 7 12:52:00 2017
*mangle
:PREROUTING ACCEPT [5456:983039]
:INPUT ACCEPT [5456:983039]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [49173:4025823]
:POSTROUTING ACCEPT [49173:4025823]
COMMIT
# Completed on Thu Sep 7 12:52:00 2017
# Generated by iptables-save v1.4.21 on Thu Sep 7 12:52:00 2017
*raw
:PREROUTING ACCEPT [5456:983039]
:OUTPUT ACCEPT [49173:4025823]
COMMIT
# Completed on Thu Sep 7 12:52:00 2017
# Generated by iptables-save v1.4.21 on Thu Sep 7 12:52:00 2017
*nat
:PREROUTING ACCEPT [0:0]
:INPUT ACCEPT [6:360]
:OUTPUT ACCEPT [472:38652]
:POSTROUTING ACCEPT [472:38652]
:ISTIO_OUTPUT - [0:0]
:ISTIO_REDIRECT - [0:0]
-A PREROUTING -m comment --comment "istio/install-istio-prerouting" -j ISTIO_REDIRECT
-A OUTPUT -p tcp -m comment --comment "istio/install-istio-output" -j ISTIO_OUTPUT
-A ISTIO_OUTPUT ! -d 127.0.0.1/32 -o lo -m comment --comment "istio/redirect-implicit-loopback" -j ISTIO_REDIRECT
-A ISTIO_OUTPUT -m owner --uid-owner 0 -m comment --comment "istio/bypass-envoy" -j RETURN
-A ISTIO_OUTPUT -d 127.0.0.1/32 -m comment --comment "istio/bypass-explicit-loopback" -j RETURN
-A ISTIO_OUTPUT -m comment --comment "istio/redirect-default-outbound" -j ISTIO_REDIRECT
-A ISTIO_REDIRECT -p tcp -m comment --comment "istio/redirect-to-envoy-port" -j REDIRECT --to-ports 15001
COMMIT

I also took a look at the stats (port 15000/clusters) and all connections from istio-ingress to httpbin had failed connections. Attempting a curl from the istio-ingress container to the pilot port (9080) of the POD ip of httpbin results in ECONNREFUSED even though inside the sample pods 9080 has a wildcard bind (0.0.0.0). Inside the pod, a connection to IP:9080 fails, although 127.0.0.1 works properly. Inside the envoy container (via docker exec) same story.

I realize there is alot of information in this bug report and perhaps it could be better presented.
If you have questions feel free to ask and i'll supply additional information. Hopefully this debugging is helpful for someone. If anyone in this issue has any ideas how to further debug, I'd be happy to try out any suggestions. Since this is 100% reproducible, solving this particular problem may result in some forward progress on this issue tracker in general.

My suspicion is the iptables rules are incorrect, although my iptables-foo lacks enough depth to know what the correct iptables should look like in the httpbin pod that has been injected. I further suspect there is some form of race condition related to the iptables setup.

I have a friend who has Istio semi-working with a helm based installation on CentOS with similar gear. He is using flannel (not calico) so I'm going to try a different CNI next to determine if possibly calico is the cause of this problem.

[ldemailly]

@sdake thanks for the detailed report,
this issue though is specifically about 503 errors we observed mid development on our shared testing cluster, I'm a bit curious about the details of your self built istio, can you put that in
https://github.com/istio/issues/issues/new (including version informations/how exactly you built from source ?)
I don't see any istioctl kube-inject in your details above, yet you have the iptables ?
also can you try running our e2e tests in your test cluster (start with pilot's test) ?

Now update about our issue for everyone else: the fix of namespace listen (#696) should cover most of the 503/weirdness but the sporadic/race based one maybe not (and those may be harder to catch now)

[sdake]

@ldemailly continued in istio/old_issues_repo#56.

[ldemailly]

this was fixed when the ingress stopped receiving all namespaces