aws-node is restarting (Crashing, exiting on 137) sporadically which causes all pods on that node to stuck on ContainerCreating state.

[daganida88]

What happened: aws-node is restarting (Crashing, exiting on 137) sporadically which causes all pods on that node to stuck on ContainerCreating state.

Attach logs aws-node {"level":"info","ts":"2021-04-13T12:24:31.015Z","caller":"entrypoint.sh","msg":"Install CNI binary.."} │ │ aws-node {"level":"info","ts":"2021-04-13T12:24:31.031Z","caller":"entrypoint.sh","msg":"Starting IPAM daemon in the background ... "} │ │ aws-node {"level":"info","ts":"2021-04-13T12:24:31.032Z","caller":"entrypoint.sh","msg":"Checking for IPAM connectivity ... "} 3:31 aws-vpc-cni-init + PLUGIN_BINS='loopback portmap bandwidth aws-cni-support.sh' │ │ aws-vpc-cni-init + for b in '$PLUGIN_BINS' │ │ aws-vpc-cni-init + '[' '!' -f loopback ']' │ │ aws-vpc-cni-init + for b in '$PLUGIN_BINS' │ │ aws-vpc-cni-init + '[' '!' -f portmap ']' │ │ aws-vpc-cni-init + for b in '$PLUGIN_BINS' │ │ aws-vpc-cni-init + '[' '!' -f bandwidth ']' │ │ aws-vpc-cni-init + for b in '$PLUGIN_BINS' │ │ aws-vpc-cni-init + '[' '!' -f aws-cni-support.sh ']' │ │ aws-vpc-cni-init Copying CNI plugin binaries ... │ │ aws-vpc-cni-init + HOST_CNI_BIN_PATH=/host/opt/cni/bin │ │ aws-vpc-cni-init + echo 'Copying CNI plugin binaries ... ' │ │ aws-vpc-cni-init + for b in '$PLUGIN_BINS' │ │ aws-vpc-cni-init + install loopback /host/opt/cni/bin │ │ aws-vpc-cni-init + for b in '$PLUGIN_BINS' │ │ aws-vpc-cni-init + install portmap /host/opt/cni/bin │ │ aws-vpc-cni-init + for b in '$PLUGIN_BINS' │ │ aws-vpc-cni-init + install bandwidth /host/opt/cni/bin │ │ aws-vpc-cni-init + for b in '$PLUGIN_BINS' │ │ aws-vpc-cni-init + install aws-cni-support.sh /host/opt/cni/bin │ │ aws-vpc-cni-init + echo 'Configure rp_filter loose... ' │ │ aws-vpc-cni-init Configure rp_filter loose... │ │ aws-vpc-cni-init ++ curl -X PUT http://169.254.169.254/latest/api/token -H 'X-aws-ec2-metadata-token-ttl-seconds: 60' │ │ aws-vpc-cni-init % Total % Received % Xferd Average Speed Time Time Time Current │ │ aws-vpc-cni-init Dload Upload Total Spent Left Speed │ │ aws-vpc-cni-init 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0100 56 100 56 0 0 56000 0 --:--:-- --:--:-- --:--:-- 56000 │ │ aws-vpc-cni-init + TOKEN=AQAEABqkV8qO_waLfVT_6TITDHDBvmAy3jkblGe9YXSpR-irRxvwJQ== │ │ aws-vpc-cni-init ++ curl -H 'X-aws-ec2-metadata-token: AQAEABqkV8qO_waLfVT_6TITDHDBvmAy3jkblGe9YXSpR-irRxvwJQ==' http://169.254.169.254/latest/meta-data/local-ipv4 │ │ aws-vpc-cni-init % Total % Received % Xferd Average Speed Time Time Time Current │ │ aws-vpc-cni-init Dload Upload Total Spent Left Speed │ │ aws-vpc-cni-init 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0100 13 100 13 0 0 13000 0 --:--:-- --:--:-- --:--:-- 13000 │ │ aws-vpc-cni-init + HOST_IP=172.19.224.26 │ │ aws-vpc-cni-init ++ ip -4 -o a │ │ aws-vpc-cni-init ++ awk '{print $2}' │ │ aws-vpc-cni-init ++ grep 172.19.224.26/ │ │ aws-vpc-cni-init + PRIMARY_IF=eth0 │ │ aws-vpc-cni-init + sysctl -w net.ipv4.conf.eth0.rp_filter=2 │ │ aws-vpc-cni-init net.ipv4.conf.eth0.rp_filter = 2 │ │ aws-vpc-cni-init + cat /proc/sys/net/ipv4/conf/eth0/rp_filter │ │ aws-vpc-cni-init 2 │ │ aws-vpc-cni-init + '[' false == true ']' │ │ aws-vpc-cni-init + sysctl -e -w net.ipv4.tcp_early_demux=1 │ │ aws-vpc-cni-init net.ipv4.tcp_early_demux = 1 │ │ aws-vpc-cni-init CNI init container done │ │ aws-vpc-cni-init + echo 'CNI init container done'

What you expected to happen: I expected the pod not to crush

How to reproduce it (as minimally and precisely as possible): Sometimes it happens sometimes it's not. but when it happens, until we don't kill the pod, the node will stay on zombie state where all pods stuck on ContainerCreating Anything else we need to know?:

Running on EKS 1.16.15 Linux Cni version: 1.7.5

[jayanthvn]

Hi @daganida88

Exit code 137 is OOM (out of memory), so does it happen on startup or after several hours of aws-node running. Can you also please check if any other process is consuming high memory, since memory allotted to the Docker containers is limited by the total available memory in the host machine and when usage increases, the available free memory may be insufficient for all the containers and hence containers may crash.

[jayanthvn]

Hi @daganida88

Can you please confirm if any other process is consuming high memory?

[jayanthvn]

Hi @daganida88

If you could share kubelet logs when the issue happens, it would help us debug.

Thanks!

[trucnguyenlam]

Please address this issue, we're experiencing the same error (it is sporadical) and there is no way we can reproduce that.

[jayanthvn]

I understand this issue happens sporadically but if you could share the information on CNI version, node and pod scale, if there is any churn with pod scale then we can try to repro the issue. Also next time when you see the issue if you could run sudo bash /opt/cni/bin/aws-cni-support.sh on the node then we can review the kubelet logs and memory consumption on the node. Also if you have any tool to monitor aws-node pod's memory consumption and verify if it not growing over time then that would rule out aws-node issue.

Thanks!

[trucnguyenlam]

@jayanthvn cni version is 1.7.5, nodes is controlled by autoscaler as recommended by eks documentation (node type is m5.large) Unfortunately, our nodes don't have ssm installed by default so we can't log in to run the command.

I'll have a look on monitoring aws-node memory consumption to check if that is the case.

Cheers!

[brettplarson]

I spoke to our AWS support rep regarding this issue and he seemed to believe that this was expected and due to the CNI container starting before the kube-proxy container became healthy. Just my 2 cents.

On Tue, Jun 15, 2021 at 4:33 PM Truc Nguyen Lam @.***> wrote:

@jayanthvn https://github.com/jayanthvn cni version is 1.7.5, nodes is controlled by autoscaler as recommended by eks documentation (node type is m5.large) Unfortunately, our nodes don't have ssm installed by default so we can't log in to run the command.

I'll have a look on monitoring aws-node memory consumption to check if that is the case.

Cheers!

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/aws/amazon-vpc-cni-k8s/issues/1425#issuecomment-861848349, or unsubscribe https://github.com/notifications/unsubscribe-auth/AIB7WSY44YL6VSZHBU26NV3TS7BJBANCNFSM423IKGDA .

[trucnguyenlam]

I'm still searching for an effective automatic approach to handle this issue, currently the only way to fix it is to manually terminate the node that is stuck.

[Legion2]

We upgraded our cluster from 1.19 to 1.20 and upgraded the unmanaged vpc-cni addon to vpc-cni 1.8.0 managed EKS Addon. Now we also experience this Issue. Somethime the containers also gets killed by its failing health and readiness probes.

  Normal   Killing    85m                    kubelet  Container aws-node failed liveness probe, will be restarted
  Normal   Pulling    85m (x2 over 106m)     kubelet  Pulling image "602401143452.dkr.ecr.eu-central-1.amazonaws.com/amazon-k8s-cni:v1.8.0-eksbuild.1"
  Normal   Created    85m (x2 over 106m)     kubelet  Created container aws-node
  Normal   Pulled     85m                    kubelet  Successfully pulled image "602401143452.dkr.ecr.eu-central-1.amazonaws.com/amazon-k8s-cni:v1.8.0-eksbuild.1" in 158.21763ms
  Normal   Started    85m (x2 over 106m)     kubelet  Started container aws-node
  Warning  Unhealthy  11m (x31 over 106m)    kubelet  Readiness probe failed:
  Warning  Unhealthy  4m57s (x28 over 100m)  kubelet  Liveness probe failed:

The node is a m5.large and it hosts 29 (of 29 possible) Pods. At the time of the last crash the node had a memory usage of 63.3% (332 MiB free memory). The pod has a constant memory usage of around 46.3 MiB as shown in the graph below:

The restart at 10 AM was triggered by a failed health probe and the restart at 11 AM was triggered by 137 exit code.

In our cluster we use resource requests and limits and the aws-node pods do not define a memory request. So they will be killed first if there is not enough memory on the node.

Note: The node was initially started with a different cni-plugin version, because of the Kubernetes version upgrade

[Legion2]

The strange thing is, that the health probes fail without a reason message after ... probe failed:

[mickael-ange]

For a month, after upgrading 4 of our EKS clusters from 1.17 to 1.20 and moving to aws-managed EKS node groups, we see appearing Readiness and Liveness failures for aws-node DaemonSet pods after we deploy/update our application deployments running in another namespace.

The error does not occur at each deployment update, only sporadically.

In the new cluster, I use the default addon, I have not upgraded them.

kubectl -n kube-system describe pod aws-node-cc26m

Normal   Scheduled  49m                default-scheduler                                         Successfully assigned kube-system/aws-node-cc26m to ip-172-26-9-103.ap-southeast-1.compute.internal
  Normal   Pulling    49m                kubelet, ip-172-26-9-103.ap-southeast-1.compute.internal  Pulling image "602401143452.dkr.ecr.ap-southeast-1.amazonaws.com/amazon-k8s-cni-init:v1.7.5-eksbuild.1"
  Normal   Pulled     49m                kubelet, ip-172-26-9-103.ap-southeast-1.compute.internal  Successfully pulled image "602401143452.dkr.ecr.ap-southeast-1.amazonaws.com/amazon-k8s-cni-init:v1.7.5-eksbuild.1" in 6.284508527s
  Normal   Created    49m                kubelet, ip-172-26-9-103.ap-southeast-1.compute.internal  Created container aws-vpc-cni-init
  Normal   Started    49m                kubelet, ip-172-26-9-103.ap-southeast-1.compute.internal  Started container aws-vpc-cni-init
  Normal   Pulling    49m                kubelet, ip-172-26-9-103.ap-southeast-1.compute.internal  Pulling image "602401143452.dkr.ecr.ap-southeast-1.amazonaws.com/amazon-k8s-cni:v1.7.5-eksbuild.1"
  Normal   Pulled     48m                kubelet, ip-172-26-9-103.ap-southeast-1.compute.internal  Successfully pulled image "602401143452.dkr.ecr.ap-southeast-1.amazonaws.com/amazon-k8s-cni:v1.7.5-eksbuild.1" in 2.246459067s
  Normal   Created    48m                kubelet, ip-172-26-9-103.ap-southeast-1.compute.internal  Created container aws-node
  Normal   Started    48m                kubelet, ip-172-26-9-103.ap-southeast-1.compute.internal  Started container aws-node
  Warning  Unhealthy  17m (x2 over 17m)  kubelet, ip-172-26-9-103.ap-southeast-1.compute.internal  Readiness probe failed:
  Warning  Unhealthy  7m52s              kubelet, ip-172-26-9-103.ap-southeast-1.compute.internal  Liveness probe failed:

I also think it is strange to not have the reason message after Liveness probe failed: and Readiness probe failed:

Regards

[Legion2]

I changed the timeoutSeconds of the aws-node livenessProbe to 5s. Since then (2 days) the pods did not restarted but the probes failed sometimes.

I also found that, all previous container restarts can be related to very high CPU utilization of the node (100%) over 30 seconds duration or longer. This is enough time for three health probe timeouts which trigger a container restart.

I think because the pod only has a cpu resource request of 10m it does not get enough cpu time to respond to the health probe in under 1 second. To guarantee such low responds times the pod requires more guaranteed cpu time. However, such a low response time is not required all the time and restarting the pod does not resolve slow response times when the node has very high cpu utilization. So increasing the health probe timeout is the only solution for this problem.

[sarbajitdutta]

@jayanthvn We have the same issue. We updated from 1.19 to 1.20 and also using CNI addons v1.8.0. aws-node keeps on restarting when cluster-autoscaler scaled up. I have tried to increase timeout for liveness probe but does not help.

[jayanthvn]

Sorry for the delayed response.

@Legion2 - Thanks for letting us know, I will look into it.

@sarbajitdutta - You mean on the new nodes the aws-node keeps restarting? Can you please share me the log lines from /var/log/aws-routed-eni/ipamd.log before a restart? Each restart will start with log line - "Starting L-..."

[mikkotimoharju]

We are also encountering these random livenessProbe failures after upgrading to EKS 1.21. Increasing the timeout helps with the restarts. The reason why this has started to happen now is a bug fix in kubernetes 1.20: Fixing Kubelet Exec Probe Timeouts and KEP-1972: kubelet exec probe timeouts. Previously the liveness and readiness probes did not respect the timeout for exec probes and the probe ran indefinitely. Now the default timeout of 1s is respected, but is sometimes too short causing it to fail and pods to restart.

[jayanthvn]

Thanks @mikkotimoharju for sharing this. We will look into it on adjusting the timeouts.

[laupow]

Another version of this story:

• EKS 1.19 (nodes still at 1.17)
• CNI is self-managed for now
• running v1.8.0-eksbuild.1

When aws-cluster-autoscaler triggers an scale up that results in 10-12 new nodes, we see the CNI plugin crash (exit 137) about the same time.

CNI restarts (a 1d rate graph)

CNI pods are crashing at the beginning of the scale event (not at scale down)

HPA scale (showing pods)

These scale events resulted in 10-12 new nodes coming online together.

Containers:
  aws-node:
    Container ID:   docker://5f77d4ef41eb097df676032c48e76745662a0c679c9018b34cf75d9ed67ee446
    Image:          602401143452.dkr.ecr.us-east-1.amazonaws.com/amazon-k8s-cni:v1.8.0-eksbuild.1
    Image ID:       docker-pullable://602401143452.dkr.ecr.us-east-1.amazonaws.com/amazon-k8s-cni@sha256:bbc7bd93b5c71ef6525d6d91883442a89e3b1d0e82781750f2cecc8bddc9e1a1
    Port:           61678/TCP
    Host Port:      61678/TCP
    State:          Running
      Started:      Tue, 24 Aug 2021 13:00:55 -0500
    Last State:     Terminated
      Reason:       Error
      Exit Code:    137
      Started:      Tue, 24 Aug 2021 12:59:18 -0500
      Finished:     Tue, 24 Aug 2021 13:00:54 -0500
    Ready:          True
    Restart Count:  1
    Requests:
      cpu:      10m
    Liveness:   exec [/app/grpc-health-probe -addr=:50051] delay=60s timeout=1s period=10s #success=1 #failure=3
    Readiness:  exec [/app/grpc-health-probe -addr=:50051] delay=1s timeout=1s period=10s #success=1 #failure=3

We aren't seeing stuck pods in ContainerCreating, though.

[jayanthvn]

Hi,

There are 2 issues mentioned here -

1. With EKS 1.21, the timeout seems to be honored because of the bug fix in 1.20 as mentioned here - https://github.com/aws/amazon-vpc-cni-k8s/issues/1425#issuecomment-901796963. This can be configured based on the load on the system. We can document this similar to Ref: Configure Probes [https://kubernetes.io/docs/tasks/configure-pod-container/configure-liveness-readiness-startup-probes/] /cc @haouc
2. During auto scaling event aws-node has crashed with error code 137 which is OOM, if you can please open a support case and share us the cni/kubelet logs it would be helpful to confirm the behavior. /cc @sarbajitdutta and @laupow

Thanks.

[achevuru]

In an ideal scenario, default timeoutSeconds value (1) should be good enough as long as the aws-node pod is not starved of CPU resources. So, even with exec probe timeout being enforced from 1.20+ we should be Ok and these values can be adjusted based on the use case (i.e.,) if you expect higher cpu load on the system, CPU resource req and timeout values can be adjusted accordingly. We can document this.

[laupow]

@jayanthvn thanks, case opened (8817394681)

From logs looks like the container can't communicate with the cluster at boot, and therefore fail healthchecks:

{"level":"info","ts":"2021-09-01T18:06:51.513Z","caller":"aws-k8s-agent/main.go:28","msg":"Starting L-IPAMD v1.8.0-eksbuild.1  ..."}
{"level":"info","ts":"2021-09-01T18:06:51.514Z","caller":"aws-k8s-agent/main.go:42","msg":"Testing communication with server"}
{"level":"info","ts":"2021-09-01T18:08:24.001Z","caller":"aws-k8s-agent/main.go:28","msg":"Starting L-IPAMD v1.8.0-eksbuild.1  ..."}
{"level":"info","ts":"2021-09-01T18:08:24.002Z","caller":"aws-k8s-agent/main.go:42","msg":"Testing communication with server"}
{"level":"info","ts":"2021-09-01T18:08:24.010Z","caller":"aws-k8s-agent/main.go:42","msg":"Successful communication with the Cluster! Cluster Version is: v1.19+. git version: v1.19.13-eks-8df270. git tree state: clean. commit: 8df2700a72a2598fa3a67c05126fa158fd839620. platform: linux/amd64"}
{"level":"warn","ts":"2021-09-01T18:08:27.030Z","caller":"awssession/session.go:64","msg":"HTTP_TIMEOUT env is not set or set to less than 10 seconds, defaulting to httpTimeout to 10sec"}
{"level":"debug","ts":"2021-09-01T18:08:27.031Z","caller":"ipamd/ipamd.go:298","msg":"Discovered region: us-east-1"}
{"level":"info","ts":"2021-09-01T18:08:27.031Z","caller":"ipamd/ipamd.go:298","msg":"Custom networking false"}
{"level":"debug","ts":"2021-09-01T18:08:27.032Z","caller":"awsutils/awsutils.go:357","msg":"Found availability zone: us-east-1f "}

[jayanthvn]

Thanks @laupow

Can you please check kube-proxy pod logs and confirm if you are seeing logs similar to below -

E0905 23:12:40.388938       7 node.go:124] Failed to retrieve node info: nodes "ip-*" not found
E0905 23:12:41.516857       7 node.go:124] Failed to retrieve node info: nodes "ip-*" not found
E0905 23:12:43.567271       7 node.go:124] Failed to retrieve node info: nodes "ip-*" not found
E0905 23:12:48.167166       7 node.go:124] Failed to retrieve node info: nodes "ip-*" not found
E0905 23:12:56.325941       7 node.go:124] Failed to retrieve node info: nodes "ip-*" not found
E0905 23:13:14.684106       7 node.go:124] Failed to retrieve node info: nodes "ip-*" not found

[laupow]

Can you please check kube-proxy pod logs and confirm if you are seeing logs similar to below -

Unfortunately I don't see those logs on any nodes with crashed CNI pods. I only see Successfully retrieved node IP. I attached full logs to the ticket.

[deva1987m]

Hi, Do we see similar issue in AWS EKS 1.21 also ?

[vioan]

Any update on this issue? We see the same problem. Will updating to 1.21 fix it?

[sstoyanovucsd]

@achevuru, the default liveness probe timeout of 1s is not enough on any cluster that runs burstable workloads allowed to scale up beyond the resources of a node. Maybe the default timeout value should be adjusted? It is also possible that bumping up resources.requests.cpu to more than 10m cores will be sufficient to allow the probe not to be starved of CPU resources and to always finish within the default 1 second.

[jayanthvn]

@laupow - sure we will check in the ticket if kube-proxy is taking time to start leading to aws-node to restart.

@deva1987m and @vioan - Sorry this thread is deviated into 2 issue as mentioned above. Are you referring to OOM killed (137) of aws-node pods? If so can you please check CPU utilization on the instance. Also I feel we need to set cpu and Memory limits for aws-node.

[sarbajitdutta]

@jayanthvn When cluster-autoscaler scales up Readiness probe fails for aws-node. Its stuck here -

I0907 16:40:46.644131      10 request.go:621] Throttling request took 1.045715446s, request: GET:https://172.20.0.1:443/apis/apiextensions.k8s.io/v1beta1?timeout=32s

The successful ones have this log messages -

{"level":"info","ts":"2021-09-07T16:40:49.507Z","caller":"entrypoint.sh","msg":"Copying config file ... "}
{"level":"info","ts":"2021-09-07T16:40:49.511Z","caller":"entrypoint.sh","msg":"Successfully copied CNI plugin binary and config file."}
{"level":"info","ts":"2021-09-07T16:40:49.512Z","caller":"entrypoint.sh","msg":"Foregrounding IPAM daemon ..."}

Error message - Readiness probe failed: {"level":"info","ts":"2021-09-07T16:46:36.839Z","caller":"/usr/local/go/src/runtime/proc.go:203","msg":"timeout: failed to connect service \":50051\" within 1s"} This causes the node to be in NotReady status forever. I am using latest version of cni and k8 version is 1.20

[AlKapkone]

Hello, any updates on this issue? Please, fix it ASAP! Thanks!

[ilcapatina]

Hi,

We had this issue when we upgraded to EKS 1.20 and I will explain our use case and how we were able to mitigate the problem.

As stated by other people in this thread, the issue started because the exec probes timeouts are honored since 1.20 . We increased the probes the timeout to 5s, 10s, or 30s, and the number of restarts dropped but there were still a few.

After further investigation, we found that the node roof EBS volumes are suffering from micro bursting (see https://aws.amazon.com/premiumsupport/knowledge-center/ebs-identify-micro-bursting/ ) during large docker image pull, causing all the running processes to be stuck for a few seconds. To mitigate this issue, we mounted another drive on the node to use it only for docker image pull. Since then, the vpc cni containers were not restarted anymore.

As I said in the beginning, this is specific to our use case.

[cam3ron2]

Any update on this issue? We see the same problem. Will updating to 1.21 fix it?

We are on 1.21 and see the same issue.