E2E test Cluster_UUID_should_have_been_preserved is flaky

[sebgl]

This happens fairly often, for any mutation where we check the ClusterUUID when done:

    --- FAIL: TestMutationMdiToDedicated/Cluster_UUID_should_have_been_preserved (64.35s)
        cluster_uuid.go:58: 
            	Error Trace:	cluster_uuid.go:58
            	Error:      	Received unexpected error:
            	            	Get https://test-mutation-mdi-to-dedicated-9j57-es-http.e2e-hbq8i-mercury.svc:9200/: dial tcp 10.91.240.2:9200: connect: no route to host
            	Test:       	TestMutationMdiToDedicated/Cluster_UUID_should_have_been_preserved

We do check the ClusterUUID in other places of the code, but we wrap the code in a test.Eventually.
Here we don't, because in theory if the mutation is over we should be able to reach the cluster.
dial tcp 10.91.240.2:9200: connect: no route to host looks like we're trying to request a Pod which doesn't exist anymore (was removed/replaced during the mutation).

We also get some errors like dial tcp 10.112.0.26:9200: connect: connection refused .

I was hoping #2233 would fix it but it looks like it's not enough.

[sebgl]

Looking at the logs of this test run where dial tcp 10.112.0.26:9200: connect: connection refused happens: 10.112.0.26 is not any of the mutated cluster Pod IPs.

It seems to match the IP address of node test-mutation-https-to-http-jdcb-es-masterdata-1 before it was upgraded according to the logs of the Elasticsearch node 0:

./e2e-fq92f-mercury/pod/test-mutation-https-to-http-jdcb-es-masterdata-0/logs.txt:{"type": "server", "timestamp": "2019-12-20T01:13:43,773+0000", "level": "INFO", "component": "o.e.c.s.ClusterApplierService", "cluster.name": "test-mutation-https-to-http-jdcb", "node.name": "test-mutation-https-to-http-jdcb-es-masterdata-0", "cluster.uuid": "ZeocfvABSoieZxIGXY6YnQ", "node.id": "-reuBXniRU2h_krFPh_yeQ",  "message": "added {{test-mutation-https-to-http-jdcb-es-masterdata-2}{k-rvDpZTSWeiD4n2Ns38Zw}{xkpq6kM-QMeGficosvyFgA}{10.112.0.26}{10.112.0.26:9300}{dim}{ml.machine_memory=2147483648, ml.max_open_jobs=20, xpack.installed=true},}, term: 1, version: 12, reason: ApplyCommitRequest{term=1, version=12, sourceNode={test-mutation-https-to-http-jdcb-es-masterdata-1}{RmShc8q1RIaN1EyHO322Xw}{PYV9aAV3R2-qCF77XKojaQ}{10.112.1.38}{10.112.1.38:9300}{dim}{ml.machine_memory=2147483648, ml.max_open_jobs=20, xpack.installed=true}}"  }
./e2e-fq92f-mercury/pod/test-mutation-https-to-http-jdcb-es-masterdata-0/logs.txt:{"type": "server", "timestamp": "2019-12-20T01:14:01,338+0000", "level": "INFO", "component": "o.e.c.s.ClusterApplierService", "cluster.name": "test-mutation-https-to-http-jdcb", "node.name": "test-mutation-https-to-http-jdcb-es-masterdata-0", "cluster.uuid": "ZeocfvABSoieZxIGXY6YnQ", "node.id": "-reuBXniRU2h_krFPh_yeQ",  "message": "removed {{test-mutation-https-to-http-jdcb-es-masterdata-2}{k-rvDpZTSWeiD4n2Ns38Zw}{xkpq6kM-QMeGficosvyFgA}{10.112.0.26}{10.112.0.26:9300}{dim}{ml.machine_memory=2147483648, ml.max_open_jobs=20, xpack.installed=true},}, term: 1, version: 37, reason: ApplyCommitRequest{term=1, version=37, sourceNode={test-mutation-https-to-http-jdcb-es-masterdata-1}{RmShc8q1RIaN1EyHO322Xw}{PYV9aAV3R2-qCF77XKojaQ}{10.112.1.38}{10.112.1.38:9300}{dim}{ml.machine_memory=2147483648, ml.max_open_jobs=20, xpack.installed=true}}"  }

Which confirms the theory that we are doing an http request against an IP that is not assigned anymore.

[sebgl]

Hypothesis discussed with @anyasabo:

• we are using the IP address from client-side DNS caching. There seems to be no DNS caching in Go, so that's probably the host-level caching. Edit: probably not since client would cache the service virtual cluster IP, not the individual Pods IPs.
• even though the Service may not have the old Endpoint anymore thanks to Minimize downtime during Pod recycling #2233, kube-proxy may still have it, and E2E tests run in a container within k8s.

Is it fine for us to just retry that http call?
We could also maybe just retry on a subset of errors (no route to host and connection refused are good examples of network-related errors?)?

[anyasabo]

Is it fine for us to just retry that http call?

I'm good with this approach. Also if it's easy to catch the specific errors you mentioned that works for me too, but I'm okay with leaving that as a refinement for later.

[sebgl]

One thing I'm not sure I understand: why do we see the old pod IP in the logs (dial tcp 10.112.0.26:9200: connect: connection refused )? I thought the client would connect to the virtual cluster IP instead and not see the individual Pod IP.

Edit: that's probably just iptables magic set up by kube-proxy. The output of iptables-save on my kube-proxy pod seems to indicate the forwarding from service to pods with a 0.33 probability for 3 pods in the services:

# iptables-save | grep .70  # grep clusterIP 
-A KUBE-SERVICES ! -s 10.16.0.0/14 -d 10.19.241.70/32 -p tcp -m comment --comment "default/elasticsearch-sample-es-http:https cluster IP" -m tcp --dport 9200 -j KUBE-MARK-MASQ
-A KUBE-SERVICES -d 10.19.241.70/32 -p tcp -m comment --comment "default/elasticsearch-sample-es-http:https cluster IP" -m tcp --dport 9200 -j KUBE-SVC-D6VNEKAUOYKY54M6

# iptables-save | grep 10.16.0.213    ## grep pod ip
-A KUBE-SEP-XQPDEUUPGVSMQKZ6 -s 10.16.0.213/32 -j KUBE-MARK-MASQ
-A KUBE-SEP-XQPDEUUPGVSMQKZ6 -p tcp -m tcp -j DNAT --to-destination 10.16.0.213:9200

# iptables-save | grep KUBE-SEP-XQPDEUUPGVSMQKZ6   # grep what seems to be related to the pod identifier
:KUBE-SEP-XQPDEUUPGVSMQKZ6 - [0:0]
-A KUBE-SEP-XQPDEUUPGVSMQKZ6 -s 10.16.0.213/32 -j KUBE-MARK-MASQ
-A KUBE-SEP-XQPDEUUPGVSMQKZ6 -p tcp -m tcp -j DNAT --to-destination 10.16.0.213:9200
-A KUBE-SVC-D6VNEKAUOYKY54M6 -m statistic --mode random --probability 0.33332999982 -j KUBE-SEP-XQPDEUUPGVSMQKZ6

I guess it may take some arbitrary time for those iptables rules to be updated, decoupled from how we see the endpoints being updated from the preStop hook.

I'm wondering if increasing $ADDITIONAL_WAIT_SECONDS in https://github.com/elastic/cloud-on-k8s/pull/2233/files#diff-a3fc667df2c386b718a6d0cb4a35ae2cR39 would be of any help.

[anyasabo]

https://kubernetes.io/docs/reference/command-line-tools-reference/kube-proxy/

--iptables-min-sync-period duration

  | The minimum interval of how often the iptables rules can be refreshed as endpoints and services change (e.g. '5s', '1m', '2h22m').

and

--iptables-sync-period duration     Default: 30s

  | The maximum interval of how often iptables rules are refreshed (e.g. '5s', '1m', '2h22m'). Must be greater than 0.

And looking at my GKE 1.12 kube-proxy config:

    - exec kube-proxy --master=https://35.195.87.186 --kubeconfig=/var/lib/kube-proxy/kubeconfig
      --cluster-cidr=10.60.0.0/14 --resource-container="" --oom-score-adj=-998 --v=2
      --feature-gates=DynamicKubeletConfig=false,RotateKubeletServerCertificate=true,ExperimentalCriticalPodAnnotation=true
      --iptables-sync-period=1m --iptables-min-sync-period=10s --ipvs-sync-period=1m
      --ipvs-min-sync-period=10s 1>>/var/log/kube-proxy.log 2>&1

And looks like the default proxy-mode is iptables. If anything I'm surprised we don't run into it more often since they set the minimum sync period to 10s and the maximum to 1m.

I think we could resolve it with ADDITIONAL_WAIT_SECONDS in the pre-stop hook, but we would probably want to wait the full minute just to be "safe". We would also need to increase the grace period to match. That would mean that every time we kill a pod we incur the wait though, which is not great. Maybe that is worthwhile to do now though so tests can pass reliably, and then we can refine the test in the future to catch those specific errors and retry?

[sebgl]

@anyasabo 👍

Some blog posts that point toward the same direction we took with the preStop hook (just double-checking our approach makes sense):

• https://freecontent.manning.com/handling-client-requests-properly-with-kubernetes/
• https://blog.sebastian-daschner.com/entries/zero-downtime-updates-kubernetes
• https://blog.laputa.io/graceful-shutdown-in-kubernetes-85f1c8d586da

A few issues & PRs that highlight the relatively "slow" iptables sync period:

• Cold start latency exacerbated by iptables-min-sync-period knative/serving#4902
• kube-proxy: ratelimit runs of iptables by sync-period flags kubernetes/kubernetes#46266
• https://github.com/kubernetes/kubernetes/blob/release-1.12/pkg/proxy/iptables/proxier.go#L354 <- where this is plugged in kube-proxy code

https://blog.laputa.io/graceful-shutdown-in-kubernetes-85f1c8d586da seems to suggest a minimum of 10sec sleeping before shutting down the Pod, to account for GKE 10sec default. I guess the 1min max is not supposed to be reached under "normal" conditions, but is still the safest value to use for us.

It will obviously slow down rolling upgrades a lot, but maybe an additional minute per Pod is still OK if it fixes the availability issue.

[david-kow]

@sebgl @anyasabo I'm not sure if we need to worry about the max one - from my look at the kube-proxy code it's only used to determine when to auto trigger the rules sync, but all the events for a service trigger the sync anyway.

The only thing that really limits this is the min sync period, but it has a burst of 2 available to it, so it's not that bad. Also, I can't find any failure of TestMutationWhileLoadTesting test which is already using ADDITIONAL_WAIT_SECONDS set to 10. I think I'd start with that as a default and then increase it if needed. WDYT?

[sebgl]

Sounds good to me, we can start with 10 seconds and see how it goes.

[sebgl]

Actually it looks like the default is 30sec on Openshift (4.1): https://docs.openshift.com/container-platform/4.1/networking/openshift-sdn/configuring-kube-proxy.html.

It does also default to 30sec on kube-proxy: https://kubernetes.io/docs/reference/command-line-tools-reference/kube-proxy/

Should we set it to 30sec instead? It sounds like a safer bet to target multiple k8s distributions.