amazon-vpc-cni-k8s: Race condition between CNI plugin install and aws-k8s-agent startup

I believe one of the reasons more people are reporting this issue now than before, is that:

• Kubernetes 1.13+ has a regression where the kubelet won’t retry PodSandbox creation for pods with a restartPolicy of Never (kubernetes/kubernetes/issues/79398) - meaning that pods get stuck as ContainerCreating after experiencing the CNI plugin race condition, and are not able to self-recover
• The above regression has been fixed in Kubernetes 1.13.8, however EKS is still running 1.13.7
• More people are now finally upgrading to EKS 1.13 now that it’s (a) generally available on AWS, (b) version 1.10 has been EOLed

@mogren since the fix for the Kubernetes regression is in kubelet, would it be possible to upgrade the version in the AMI to 1.13.8 as a stop-gap until the control plane can also be upgraded so that it’s in sync? (See aws/containers-roadmap/issues/411)

This is happening to us as well.

CNI version: 602401143452.dkr.ecr.eu-west-1.amazonaws.com/amazon-k8s-cni:v1.5.0 EKS version: v1.13.7-eks-c57ff8

Is there a fix coming down the pipeline for this? It’s legitimately affecting production workloads right now.

I’m in the same situation as @kc8apf. We are using EKS+Autoscalar to run out Gitlab CI runner. The cluster version is 1.13 eks.2 and CNI version is 1.5.0.

Sometimes the pod is stuck at ContainerCreating stage and its description is like:

Events:
  Type     Reason                  Age              From                                                 Message
  ----     ------                  ----             ----                                                 -------
  Warning  FailedScheduling        4m (x2 over 4m)  default-scheduler                                    0/3 nodes are available: 1 node(s) didn't match node selector, 3 Insufficient cpu.
  Normal   TriggeredScaleUp        4m               cluster-autoscaler                                   pod triggered scale-up: [{gitlab-x86-64-asg 3->4 (max: 16)}]
  Warning  FailedScheduling        4m (x2 over 4m)  default-scheduler                                    0/4 nodes are available: 1 node(s) didn't match node selector, 1 node(s) had taints that the pod didn't tolerate, 3 Insufficient cpu.
  Normal   Scheduled               3m               default-scheduler                                    Successfully assigned default/runner-ex6ucuta-project-136-concurrent-48nnx7 to ip-172-31-2-101.us-west-2.compute.internal
  Warning  FailedCreatePodSandBox  3m               kubelet, ip-172-31-2-101.us-west-2.compute.internal  Failed create pod sandbox: rpc error: code = Unknown desc = [failed to set up sandbox container "d6f10d64bd0133c14aa4e95cf50565c459198f652656b254dd09745c713e24e5" network for pod "runner-ex6ucuta-project-136-concurrent-48nnx7": NetworkPlugin cni failed to set up pod "runner-ex6ucuta-project-136-concurrent-48nnx7_default" network: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:50051: connect: connection refused", failed to clean up sandbox container "d6f10d64bd0133c14aa4e95cf50565c459198f652656b254dd09745c713e24e5" network for pod "runner-ex6ucuta-project-136-concurrent-48nnx7": NetworkPlugin cni failed to teardown pod "runner-ex6ucuta-project-136-concurrent-48nnx7_default" network: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:50051: connect: connection refused"]

This only happens when a new node scaling-up is triggered by new jobs. After that, this node isn’t able to take any pods because of this CNI failure.

I compared the ipamd.log between a successful node and a failed node,

successful_ipamd.log.2019-07-02-18.log failed_ipamd.log.2019-07-02-18.log

An interesting finding is that, on the successful node, pod IP assignment happened after all the 30 IP have been added. Note that log Add/Update for Pod runner-xxx first showed up on line 156, after all the Added ENI(....

However on the failed node, the pod tries to get an IP(description not accurate) before the ENI was even added! Starting from line 58, it tried 12 times to get an IP but failed apparently because the CNI is not ready. After 12 attempts, it gave up and then the CNI had the chance to add 30 IP to the IP pool.

Any thought on how to coordinate the starting sequence? Thanks

We created a custom AMI with kubelet version 1.13.8 and we can confirm it fixes this issue. Also, control plane is now on 1.13.8, is the new AMI coming anytime soon?

@Mewzyk I just made a release candidate with a potential fix of this issue. It’s not yet a final release and we are still doing testing, but if you would like to test the build the instructions are here:

https://github.com/aws/amazon-vpc-cni-k8s/releases/tag/v1.5.1-rc1

@mogren I am facing a similar issue new pod is getting scheduled to a node.

Failed to create pod sandbox: rpc error: code = Unknown desc = [failed to set up sandbox container "9f3dcceb6da3b53d10af353d83b374cf4359d38d85da5cc813925f58f02a232c" network for pod "nginx-deployment-56c774d974-kqgcm":
 networkPlugin cni failed to set up pod "nginx-deployment-56c774d974-kqgcm_nginx-example" network: add cmd: Error received from AddNetwork gRPC call: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:50051: connect: connection refused", 
failed to clean up sandbox container "9f3dcceb6da3b53d10af353d83b374cf4359d38d85da5cc813925f58f02a232c" network for pod "nginx-deployment-56c774d974-kqgcm": networkPlugin cni failed to teardown pod "nginx-deployment-56c774d974-kqgcm_nginx-example"
 network: del cmd: error received from DelNetwork gRPC call: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:50051: connect: connection refused"]

EKS: 1.17 aws cni : 1.7.5

I can confirm another configuration that works - as of today: 2019-08-13.

• EKS K8S control plane is v1.13.8-eks-a977ba (from kubectl version)
• EKS kubelets on the worker nodes are v1.13.7-eks-c57ff8 (from kubectl get node)
• Manually updated aws-cni daemonset to v1.5.3 (kubectl edit ds -n kubesystem aws-cni)
• Cluster autoscaler is v1.15.1

I posted a job with a specific affinity and toleration to target an ASG that had 0 nodes in it. Cluster autoscaler added a node to the ASG. When the node became ready, there was a little delay, but no FailedCreatePodSandBox errors in the pod events.

Fixed for new nodes in v1.5.3, and merged back to master.

@mattmi88 Ditto!

Thanks for the update.

A note, the recent v1.5.1 release does not have the startup fix! I will make a v1.5.2 soon with the quick config fix plus the changes currently in v1.5.1-rc1.

A solution could be to run 2 containers in the daemonset. 1 to install the CNI and one that runs /app/aws-k8s-agent. The one that install the CNI can do a grpc health check or call an endpoint to check that /app/aws-k8s-agent is fully up and running before installing the CNI. Calico for example runs 2 containers in the daemonset: https://docs.projectcalico.org/v3.1/getting-started/kubernetes/installation/hosted/calico.yaml

However they do not have any coordination between them in the install CNI script: https://github.com/projectcalico/cni-plugin/blob/master/k8s-install/scripts/install-cni.sh