search

aws / amazon-vpc-cni-k8s

Networking plugin repository for pod networking in Kubernetes using Elastic Network Interfaces on AWS
Apache License 2.0
2.24k stars 727 forks source link

VPC CNI stuck in crash loop without insights #2945

Open duxing opened 1 month ago

duxing commented 1 month ago

What happened:

I'm working on testing autoscaling for my EKS cluster (1.29) and karpenter is frequently scaling nodes up and down during my test. At a certain point, all newly launched nodes stuck in NotReady due to VPC CNI pod stuck in crash loop.

The symptom is very similar to hitting EC2/ENI API rate limit, however, I can't find out useful logs / metrics from the client (VPC CNI pod) to help me confirm/diagnose, despite AWS_VPC_K8S_CNI_LOGLEVEL is set to DEBUG (AWS_VPC_K8S_PLUGIN_LOG_LEVEL is also DEBUG if it matters)

The version i'm using is v1.18.1-eksbuild.3 (the EKS optimized addon) and the logs are attached below.

Attach logs

unable to run sudo bash /opt/cni/bin/aws-cni-support.sh: the image 602401143452.dkr.ecr.us-east-1.amazonaws.com/amazon-k8s-cni:v1.18.1-eksbuild.3 seems to be distroless

logs from kubectl logs -f ...:

successfully launched aws-node pod (AWS_VPC_K8S_CNI_LOGLEVEL=DEBUG):

Installed /host/opt/cni/bin/aws-cni Installed /host/opt/cni/bin/egress-cni time="2024-06-04T23:27:31Z" level=info msg="Starting IPAM daemon... " time="2024-06-04T23:27:31Z" level=info msg="Checking for IPAM connectivity... " time="2024-06-04T23:27:33Z" level=info msg="Copying config file... " time="2024-06-04T23:27:33Z" level=info msg="Successfully copied CNI plugin binary and config file."

stuck aws-node pod (also AWS_VPC_K8S_CNI_LOGLEVEL=DEBUG):

Installed /host/opt/cni/bin/aws-cni Installed /host/opt/cni/bin/egress-cni time="2024-06-05T03:40:00Z" level=info msg="Starting IPAM daemon... " time="2024-06-05T03:40:00Z" level=info msg="Checking for IPAM connectivity... " // stuck here indefinitely until container is restarted

What you expected to happen:

with AWS_VPC_K8S_CNI_LOGLEVEL=DEBUG, logs should be more verbose, spitting out information about what the process is doing. whatever error/exception that caused initialization failure should be surfaced to the log stream under pretty much any log level (should be ERROR log level for these entries)

if there are exponential backoff retry for 429 responses, it needs to be surfaced during verbose mode (debug log level)

How to reproduce it (as minimally and precisely as possible):

Anything else we need to know?:

Environment:

orsenthil commented 1 month ago

sudo bash /opt/cni/bin/aws-cni-support.sh should be run from the node where you are observing the crash loop. Can you also see what the ipamd.log and plugin.log say in the same node. They are located in /var/log/aws-routed-eni/ipamd.log and /var/log/aws-routed-eni/plugin.log

duxing commented 1 month ago

@orsenthil thx for the clarification. I missed the window when this issue can be consistently reproduced (I suspect it has something to do with AWS API rate limiting) and I'm unable to reproduce this right now, but I'll check if I can find the logs from the affected nodes from that time.

update: unable to do that. the daemonset pod failed initialization due to VPC CNI stuck in crash loop. I may have to reproduce this again to see the logs

however, I did get your point about the log verbosity setting is affecting the /var/log/aws-routed-eni/ipamd.log file, and I think this issue can be closed.

would you recommend setting AWS_VPC_K8S_CNI_LOG_FILE to be /dev/stdout to make the logs available for kubectl logs -f?

duxing commented 1 month ago

I was to reproduce this on an EKS node that I have SSH access to and the results have been sent to k8s-awscni-triage@amazon.com

after going through ipamd.log and other log files under /var/log/aws-routed-eni/, I couldn't find any useful log lines that can help me confirm if this is a rate limit issue or identify what's causing the failure.

as this comment is written, the node has been in this state for 19m (together with many nodes that are stuck for 40mins):

kubectl get nodes --sort-by=.metadata.creationTimestamp
...
ip-10-231-76-39.ec2.internal     Ready      <none>   33h     v1.29.0-eks-5e0fdde
ip-10-231-75-201.ec2.internal    Ready      <none>   159m    v1.29.0-eks-5e0fdde
ip-10-231-107-179.ec2.internal   NotReady   <none>   37m     v1.29.0-eks-5e0fdde
...
ip-10-231-87-255.ec2.internal    NotReady   <none>   19m     v1.29.0-eks-5e0fdde

if it helps: I managed to launch 1 node 159ms ago (pool is homogenous): after this issue is reported but before this current response.

I guess the "issue" I have is: the ipamd log or kubectl logs -f should provide some insights on why this particular failure is happening

duxing commented 1 month ago

posted some of my own findings in a separate issue #2948

the logs uploaded for this issue have the same issue as the example logs in #2948