Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Huge network connections latencies after installing Calico in an EKS cluster #3530

Closed
joseapena opened this issue May 8, 2020 · 6 comments · Fixed by projectcalico/libcalico-go#1523

Comments

@joseapena
Copy link

joseapena commented May 8, 2020

After installing Calico following AWS's instructions in an EKS cluster, the time for pods to establish a new connection is more than 10 seconds. Subsequent connections are, in general, much faster, but the first one usually can take more than 10 seconds.

No network policies have been created.

The issue disappears when calico is removed and iptables are flushed. The latter step is important.

Expected Behavior

Connections with external and internal IP addresses should be established in less than 1 second.

Current Behavior

The first connections that the pod tries to establish are taking more than 10 seconds on average. Usually, only the first connection takes this long time and the subsequent ones are much faster, although I've also seen some timeouts appearing after a container was running for more than 20 minutes.

When running a pod that executes the following script:

          time curl -k --connect-timeout 10  -o /dev/null --header "X-Consul-Token:anonymous"  https://10.198.145.51:8501/v1/kv/config/application/kafka/ssl/CACert?raw &&
          time curl -k --connect-timeout 10  -o /dev/null --header "X-Consul-Token:anonymous"  https://10.198.145.51:8501/v1/kv/config/application/kafka/ssl/CACert?raw &&
          time curl -k --connect-timeout 10  -o /dev/null https://10.198.146.250 &&
          time curl -k --connect-timeout 10  -o /dev/null https://10.198.146.250 &&
          echo "SUCCESS" ||
          echo "FAILED";
          tail -f /dev/null;

Most pods fail while just a few can start without problems. This is an example of the type of errors that I can see:

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:--  0:00:10 --:--:--     0
curl: (28) Connection timed out after 10001 milliseconds

real	0m10.014s
user	0m0.015s
sys	0m0.000s
FAILED

This is the output of a pod that started successfully. The first connection takes 7 seconds while the next ones are much faster:

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  1220  100  1220    0     0    169      0  0:00:07  0:00:07 --:--:--   305

real	0m7.211s
user	0m0.022s
sys	0m0.005s
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  1220  100  1220    0     0  71764      0 --:--:-- --:--:-- --:--:-- 71764

real	0m0.029s
user	0m0.016s
sys	0m0.006s
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100    40  100    40    0     0   2222      0 --:--:-- --:--:-- --:--:--  2222

real	0m0.029s
user	0m0.016s
sys	0m0.005s
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100    40  100    40    0     0   2000      0 --:--:-- --:--:-- --:--:--  2105

real	0m0.031s
user	0m0.018s
sys	0m0.004s
SUCCESS

Connection latencies and the number of time-outs seem to increase when starting multiple containers simultaneously.

Looking at Calico logs I can see that the problem is that containers are starting before Calico has written the IP tables. For instance:

This is the output of the application, showing a delay of 15 seconds. In this case I started 10 containers in parallel (when starting only 1 container everything is perfect and there are no delays).

12:06:07.183097107
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
12:06:22.481623342
100    39  100    39    0     0      2      0  0:00:19  0:00:15  0:00:04     9

I can find the following lines in the calico logs:

sort -u calico.log | grep 'Writing'
2020-05-09 12:06:22.166 [DEBUG][41] ipsets.go 840: Writing add family="inet" member=10.198.145.201/32 numDeltaAdds=1 numDeltaDeletes=0 numMembersInDataplane=92 setID="s:Vbl4aLpsO8Ss0UCzvsdmKAp4rZRC-V4hJGyiGg"
2020-05-09 12:06:22.276 [DEBUG][41] table.go 1078: Writing to iptables ipVersion=0x4 iptablesInput="*filter\n:cali-from-wl-dispatch-c - -\n:cali-to-wl-dispatch-c - -\n:cali-pro-ksa.toolbox.toolbox - -\n:cali-pri-kns.toolbox - -\n:cali-pro-kns.toolbox - -\n:cali-pri-ksa.toolbox.toolbox - -\n:cali-tw-enic72a72146bc - -\n:cali-fw-enic72a72146bc - -\n-A cali-tw-enic72a72146bc -m comment --comment \"cali:lcEXIK-2Oo9tuge2\" -m conntrack --ctstate RELATED,ESTABLISHED --jump ACCEPT\n-A cali-tw-enic72a72146bc -m comment --comment \"cali:Andg7sWrNV4b73QJ\" -m conntrack --ctstate INVALID --jump DROP\n-A cali-tw-enic72a72146bc -m comment --comment \"cali:AGK_ghHF9V-lAs-I\" --jump MARK --set-mark 0/0x10000\n-A cali-tw-enic72a72146bc -m comment --comment \"cali:si9o_LBOLKSk18N8\" --jump cali-pri-kns.toolbox\n-A cali-tw-enic72a72146bc -m comment --comment \"cali:zi_a4_lQDy1OaC6e\" -m comment --comment \"Return if profile accepted\" -m mark --mark 0x10000/0x10000 --jump RETURN\n-A cali-tw-enic72a72146bc -m comment --comment \"cali:xFacVicGd7rfUvhr\" --jump cali-pri-ksa.toolbox.toolbox\n-A cali-tw-enic72a72146bc -m comment --comment \"cali:EP4Xjt9Ii2oJU6GQ\" -m comment --comment \"Return if profile accepted\" -m mark --mark 0x10000/0x10000 --jump RETURN\n-A cali-tw-enic72a72146bc -m comment --comment \"cali:U2gllQYFAh4XOe4l\" -m comment --comment \"Drop if no profiles matched\" --jump DROP\n-A cali-fw-enic72a72146bc -m comment --comment \"cali:XVgKSMt1QbQvluyr\" -m conntrack --ctstate RELATED,ESTABLISHED --jump ACCEPT\n-A cali-fw-enic72a72146bc -m comment --comment \"cali:XPwKgOT8qE3grC7S\" -m conntrack --ctstate INVALID --jump DROP\n-A cali-fw-enic72a72146bc -m comment --comment \"cali:yrnI3Z8HbdAlul0h\" --jump MARK --set-mark 0/0x10000\n-A cali-fw-enic72a72146bc -m comment --comment \"cali:74Hp4qNQcrm2-z45\" -m comment --comment \"Drop VXLAN encapped packets originating in pods\" -p 17 -m multiport --destination-ports 4789 --jump DROP\n-A cali-fw-enic72a72146bc -m comment --comment \"cali:wl-ptfe8K6nYu5z3\" -m comment --comment \"Drop IPinIP encapped packets originating in pods\" -p 4 --jump DROP\n-A cali-fw-enic72a72146bc -m comment --comment \"cali:WXfkIt9NhbQk8DOO\" --jump cali-pro-kns.toolbox\n-A cali-fw-enic72a72146bc -m comment --comment \"cali:Gt6mxplKNqHvYzzI\" -m comment --comment \"Return if profile accepted\" -m mark --mark 0x10000/0x10000 --jump RETURN\n-A cali-fw-enic72a72146bc -m comment --comment \"cali:W9m-vSYMi0FPBNdh\" --jump cali-pro-ksa.toolbox.toolbox\n-A cali-fw-enic72a72146bc -m comment --comment \"cali:ZRm1Q4tRJ-sASh_U\" -m comment --comment \"Return if profile accepted\" -m mark --mark 0x10000/0x10000 --jump RETURN\n-A cali-fw-enic72a72146bc -m comment --comment \"cali:iDQeZvFyttpekWz5\" -m comment --comment \"Drop if no profiles matched\" --jump DROP\n-A cali-from-wl-dispatch-c -m comment --comment \"cali:S7V0FCKX_y_y31gp\" --in-interface enic72a72146bc --goto cali-fw-enic72a72146bc\n-A cali-from-wl-dispatch-c -m comment --comment \"cali:g3qbsVR1sLA1aupN\" --in-interface enice05e9a89d5 --goto cali-fw-enice05e9a89d5\n-A cali-from-wl-dispatch-c -m comment --comment \"cali:ko-IGFiBzeO-7lA6\" -m comment --comment \"Unknown interface\" --jump DROP\n-R cali-from-wl-dispatch 11 -m comment --comment \"cali:b1de_6JW-gqi2we6\" --in-interface enic+ --goto cali-from-wl-dispatch-c\n-R cali-from-wl-dispatch 12 -m comment --comment \"cali:n3XcFmKK9c89XrLX\" --in-interface enie4a2348e81d --goto cali-fw-enie4a2348e81d\n-R cali-from-wl-dispatch 13 -m comment --comment \"cali:kEQz1NfCkdX6F9yo\" -m comment --comment \"Unknown interface\" --jump DROP\n-A cali-to-wl-dispatch-c -m comment --comment \"cali:gR6KLngSeIVPJ_7W\" --out-interface enic72a72146bc --goto cali-tw-enic72a72146bc\n-A cali-to-wl-dispatch-c -m comment --comment \"cali:NLI8IDNMNiO1qozI\" --out-interface enice05e9a89d5 --goto cali-tw-enice05e9a89d5\n-A cali-to-wl-dispatch-c -m comment --comment \"cali:HS-FEjDOvyCbWJDf\" -m comment --comment \"Unknown interface\" --jump DROP\n-R cali-to-wl-dispatch 11 -m comment --comment \"cali:3c82IZa1bjjyoGTg\" --out-interface enic+ --goto cali-to-wl-dispatch-c\n-R cali-to-wl-dispatch 12 -m comment --comment \"cali:hi3Nbx0-bRgRWBDP\" --out-interface enie4a2348e81d --goto cali-tw-enie4a2348e81d\n-R cali-to-wl-dispatch 13 -m comment --comment \"cali:4P-R0UnJhDhPHskA\" -m comment --comment \"Unknown interface\" --jump DROP\n-A cali-pri-kns.toolbox -m comment --comment \"cali:SDWeUTWdEN1l151w\" --jump MARK --set-mark 0x10000/0x10000\n-A cali-pri-kns.toolbox -m comment --comment \"cali:oOeBCn6dF2BCxoj_\" -m mark --mark 0x10000/0x10000 --jump RETURN\n-A cali-pro-kns.toolbox -m comment --comment \"cali:WLU8lzvsbmTmYVsP\" --jump MARK --set-mark 0x10000/0x10000\n-A cali-pro-kns.toolbox -m comment --comment \"cali:JgyTymbl59FZxr7b\" -m mark --mark 0x10000/0x10000 --jump RETURN\nCOMMIT\n" table="filter"
2020-05-09 12:06:25.368 [DEBUG][41] ipsets.go 840: Writing add family="inet" member=10.198.145.207/32 numDeltaAdds=1 numDeltaDeletes=0 numMembersInDataplane=93 setID="s:Vbl4aLpsO8Ss0UCzvsdmKAp4rZRC-V4hJGyiGg"
2020-05-09 12:06:25.499 [DEBUG][41] table.go 1078: Writing to iptables ipVersion=0x4 iptablesInput="*filter\n:cali-tw-eni6760c4fa8f5 - -\n:cali-fw-eni6760c4fa8f5 - -\n:cali-from-wl-dispatch-6 - -\n:cali-to-wl-dispatch-6 - -\n-A cali-fw-eni6760c4fa8f5 -m comment --comment \"cali:S5ha2OJdZeGSQD83\" -m conntrack --ctstate RELATED,ESTABLISHED --jump ACCEPT\n-A cali-fw-eni6760c4fa8f5 -m comment --comment \"cali:SC6JVvL7RvoKu0Qn\" -m conntrack --ctstate INVALID --jump DROP\n-A cali-fw-eni6760c4fa8f5 -m comment --comment \"cali:uFwqwt-DPKE5_ZGN\" --jump MARK --set-mark 0/0x10000\n-A cali-fw-eni6760c4fa8f5 -m comment --comment \"cali:a9NfCbPcDVSNeuh5\" -m comment --comment \"Drop VXLAN encapped packets originating in pods\" -p 17 -m multiport --destination-ports 4789 --jump DROP\n-A cali-fw-eni6760c4fa8f5 -m comment --comment \"cali:HlnPFPUqT-PZIJXY\" -m comment --comment \"Drop IPinIP encapped packets originating in pods\" -p 4 --jump DROP\n-A cali-fw-eni6760c4fa8f5 -m comment --comment \"cali:vhT6TKhaBFj_c3yJ\" --jump cali-pro-kns.toolbox\n-A cali-fw-eni6760c4fa8f5 -m comment --comment \"cali:e_6v_6NqlAb3wcZi\" -m comment --comment \"Return if profile accepted\" -m mark --mark 0x10000/0x10000 --jump RETURN\n-A cali-fw-eni6760c4fa8f5 -m comment --comment \"cali:wPp_h5y-KTcF4bSt\" --jump cali-pro-ksa.toolbox.toolbox\n-A cali-fw-eni6760c4fa8f5 -m comment --comment \"cali:201CdedkJMamKqzm\" -m comment --comment \"Return if profile accepted\" -m mark --mark 0x10000/0x10000 --jump RETURN\n-A cali-fw-eni6760c4fa8f5 -m comment --comment \"cali:2QnGi68w4RNx_ovH\" -m comment --comment \"Drop if no profiles matched\" --jump DROP\n-A cali-from-wl-dispatch-6 -m comment --comment \"cali:-cez3qJ7deM-9wIg\" --in-interface eni627629752f5 --goto cali-fw-eni627629752f5\n-A cali-from-wl-dispatch-6 -m comment --comment \"cali:iEykeLAj7nblfl5G\" --in-interface eni6760c4fa8f5 --goto cali-fw-eni6760c4fa8f5\n-A cali-from-wl-dispatch-6 -m comment --comment \"cali:ESO7njKLDtZ3P5v_\" -m comment --comment \"Unknown interface\" --jump DROP\n-R cali-from-wl-dispatch 6 -m comment --comment \"cali:qNW-2o_0x427rXRw\" --in-interface eni6+ --goto cali-from-wl-dispatch-6\n-R cali-from-wl-dispatch 7 -m comment --comment \"cali:StoZpbPWKSJPQRkN\" --in-interface eni8061986efa6 --goto cali-fw-eni8061986efa6\n-R cali-from-wl-dispatch 8 -m comment --comment \"cali:q0sn3ZyUUzk9B1Gv\" --in-interface eni99edeb990a0 --goto cali-fw-eni99edeb990a0\n-R cali-from-wl-dispatch 9 -m comment --comment \"cali:BkQXjQurYmPFQ6ld\" --in-interface enia84e54e50e1 --goto cali-fw-enia84e54e50e1\n-R cali-from-wl-dispatch 10 -m comment --comment \"cali:mNJogcaBwlOuAA8P\" --in-interface enib+ --goto cali-from-wl-dispatch-b\n-R cali-from-wl-dispatch 11 -m comment --comment \"cali:IOWVM-HQvb68u7yp\" --in-interface enic+ --goto cali-from-wl-dispatch-c\n-R cali-from-wl-dispatch 12 -m comment --comment \"cali:FuRsEeMGq7F28cYM\" --in-interface enie4a2348e81d --goto cali-fw-enie4a2348e81d\n-R cali-from-wl-dispatch 13 -m comment --comment \"cali:RV-LabhFKr3m3M-2\" -m comment --comment \"Unknown interface\" --jump DROP\n-A cali-to-wl-dispatch-6 -m comment --comment \"cali:kAAS_KYRlFhSdG_l\" --out-interface eni627629752f5 --goto cali-tw-eni627629752f5\n-A cali-to-wl-dispatch-6 -m comment --comment \"cali:cuSnVWaX-vYC0KFB\" --out-interface eni6760c4fa8f5 --goto cali-tw-eni6760c4fa8f5\n-A cali-to-wl-dispatch-6 -m comment --comment \"cali:d7KqXIAYM71ht3KW\" -m comment --comment \"Unknown interface\" --jump DROP\n-R cali-to-wl-dispatch 6 -m comment --comment \"cali:dKmuxaKonm0_yi5b\" --out-interface eni6+ --goto cali-to-wl-dispatch-6\n-R cali-to-wl-dispatch 7 -m comment --comment \"cali:QMvYJuClvZJA5T9H\" --out-interface eni8061986efa6 --goto cali-tw-eni8061986efa6\n-R cali-to-wl-dispatch 8 -m comment --comment \"cali:ODzkaAiNT0U2srkv\" --out-interface eni99edeb990a0 --goto cali-tw-eni99edeb990a0\n-R cali-to-wl-dispatch 9 -m comment --comment \"cali:3KfnrRLRp1znHqCY\" --out-interface enia84e54e50e1 --goto cali-tw-enia84e54e50e1\n-R cali-to-wl-dispatch 10 -m comment --comment \"cali:eK-Fn_PDL8el30db\" --out-interface enib+ --goto cali-to-wl-dispatch-b\n-R cali-to-wl-dispatch 11 -m comment --comment \"cali:UZ5K0a2ZfojXBzjO\" --out-interface enic+ --goto cali-to-wl-dispatch-c\n-R cali-to-wl-dispatch 12 -m comment --comment \"cali:Ch4qYlIB45AQytcK\" --out-interface enie4a2348e81d --goto cali-tw-enie4a2348e81d\n-R cali-to-wl-dispatch 13 -m comment --comment \"cali:Q2nMLaHp7gIiZ8yz\" -m comment --comment \"Unknown interface\" --jump DROP\n-A cali-tw-eni6760c4fa8f5 -m comment --comment \"cali:FLMqRk41qu32Vikz\" -m conntrack --ctstate RELATED,ESTABLISHED --jump ACCEPT\n-A cali-tw-eni6760c4fa8f5 -m comment --comment \"cali:-of-Kl6kwz8_882M\" -m conntrack --ctstate INVALID --jump DROP\n-A cali-tw-eni6760c4fa8f5 -m comment --comment \"cali:WilWbvHPmSPqUqIT\" --jump MARK --set-mark 0/0x10000\n-A cali-tw-eni6760c4fa8f5 -m comment --comment \"cali:WXWvGt7TkuH74l06\" --jump cali-pri-kns.toolbox\n-A cali-tw-eni6760c4fa8f5 -m comment --comment \"cali:iBGJ7QoHq1VrXA1l\" -m comment --comment \"Return if profile accepted\" -m mark --mark 0x10000/0x10000 --jump RETURN\n-A cali-tw-eni6760c4fa8f5 -m comment --comment \"cali:nEx_t6LiQHjcKz5q\" --jump cali-pri-ksa.toolbox.toolbox\n-A cali-tw-eni6760c4fa8f5 -m comment --comment \"cali:iopkfIZaMbUxv7Xh\" -m comment --comment \"Return if profile accepted\" -m mark --mark 0x10000/0x10000 --jump RETURN\n-A cali-tw-eni6760c4fa8f5 -m comment --comment \"cali:xZClzbuledtzkk84\" -m comment --comment \"Drop if no profiles matched\" --jump DROP\nCOMMIT\n" table="filter"

So it seems that the problem is that Calico is taking 15 seconds to flush the IP Tables.

Steps to Reproduce (for bugs)

  1. Setup an EKS cluster based on K8s 1.13
  2. Install Calico following AWS's instructions available here: https://github.com/aws/amazon-vpc-cni-k8s/blob/v1.5.7/config/v1.5/calico.yaml
  3. Deploy the following sts
apiVersion: apps/v1
kind: StatefulSet
metadata:
  name: release-name-toolbox
  namespace: "hal-push-apps"
  labels:
    app.kubernetes.io/name: toolbox
    app.kubernetes.io/instance: release-name
spec:
  serviceName: release-name-toolbox
  replicas: 50
  podManagementPolicy: Parallel
  selector:
    matchLabels:
      app.kubernetes.io/name: toolbox
      app.kubernetes.io/instance: "release-name"
  template:
    metadata:
      labels:
        app.kubernetes.io/name: toolbox
        app.kubernetes.io/instance: "release-name"
    spec:
      imagePullSecrets:
        - name: artifactory-registry
      securityContext:
        fsGroup: 1000
        runAsUser: 1000
      dnsConfig:
        options:
        - name: ndots
          value: "1"
        # - name: timeout
        #   value: "30"
        # - name: attempts
        #   value: "5"
      containers:
      - name: toolbox
        args:
        - time curl -k --connect-timeout 10  -o /dev/null --header "X-Consul-Token:anonymous"  https://10.198.145.51:8501/v1/kv/config/application/kafka/ssl/CACert?raw &&
          time curl -k --connect-timeout 10  -o /dev/null --header "X-Consul-Token:anonymous"  https://10.198.145.51:8501/v1/kv/config/application/kafka/ssl/CACert?raw &&
          time curl -k --connect-timeout 10  -o /dev/null https://10.198.146.250 &&
          time curl -k --connect-timeout 10  -o /dev/null https://10.198.146.250 &&
          echo "SUCCESS" ||
          echo "FAILED";
          tail -f /dev/null;
        command:
        - /bin/bash
        - -c
        image: "docker.artifactory.eu-west-2.aws.uk.hal/devops-docker-local/toolbox:latest"
  1. Check the logs

Context

This issue makes many systems fail during container start-up with time-out errors. It has a huge impact on DNS resolution as the default time-out is 5 seconds and most lookups fail.

Increasing the timeout in /etc/resolv.conf helps but that's just a workaround.

Your Environment

  • Using Kubernetes 1.13
  • CNI driver: v1.5.7
  • Calico: v3.3.6
  • Worker nodes run Ubuntu 18.04 optimized for EKS (but tested with AWS Linux 2 and fails too)

calico.log

@joseapena
Copy link
Author

This issue is also described here: aws/amazon-vpc-cni-k8s#493

@caseydavenport
Copy link
Member

There's a known issue with the kubelet not writing pod IP addresses back into the Kubernetes API quickly enough. I raised this upstream back in 2016: kubernetes/kubernetes#39113

The TLDR is that kubelet doesn't update the address quickly enough and so Calico is blocked on programming policy until that address is in the API.

If you're using the Calico CNI plugin, there is a workaround that bypasses the kubelet for writing the IP which make sure that policy is programmed fast. However, non-Calico CNI plugins (like the Amazon VPC plugin) don't have that logic, and so rely on the kubelet to program the IP into the API.

I suspect that this is what you're encountering.

@joseapena
Copy link
Author

Thank you very much for your response. I guess there is nothing to do if I want to keep using the VPC CNI plugin.

@alaytonoracle
Copy link

alaytonoracle commented Mar 31, 2021

@caseydavenport Casey, above you mentioned "If you're using the Calico CNI plugin, there is a workaround that bypasses the kubelet for writing the IP which make sure that policy is programmed fast. However, non-Calico CNI plugins (like the Amazon VPC plugin) don't have that logic, and so rely on the kubelet to program the IP into the API."

Could you please provide details on this workaround using the Calico CNI plugin? Thanks.

@caseydavenport
Copy link
Member

@alaytonoracle the Calico CNI plugin writes the IP address back to the pod as an annotation to close the race-condition window caused by the kubelet's update batching delay. Once the kubelet updates the pod status, then the annotation will be ignored moving forward.

@alaytonoracle
Copy link

@caseydavenport Thanks. But in the case of a k8s job, each job creates a new pod - so the delays occur every time under heavy volumes. I'm not clear if there is a workaround for this. If not, do you know if there's any ETA for a fix for the root issue? Thanks for the help.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants