amazon-eks-ami 🚀 - Nodes become unresponsive and doesnt recover with soft lockup error

Ever since I moved to new kernel for 1.14 I am facing lot of issues in the nodes and nodes are going out quite frequently.Some times it doesn't become responsive and be in the ready status and sometimes it just flips to node not ready status. Is there any bug in Kernel which I am hitting into ?
If there is any customization which is not relevant to the 1.14 , I can do the changes and test.
Any suggestions would be greatly welcome

Following are the soft lock up messages seen

kernel: ena 0000:00:08.0 eth3: Found a Tx that wasn't completed on time, qid 4, index 787.
kernel: watchdog: BUG: soft lockup - CPU#58 stuck for 23s! [kworker/u146:7:707658]
kernel: Modules linked in: rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver nfs lockd grace fscache xfrm_user xfrm_algo br_netfilter bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6_tables veth iptable_mangle xt_connmark nf_conntrack_netlink nfnetlink xt_statistic xt_recent ipt_REJECT nf_reject_ipv4 xt_addrtype xt_nat xt_tcpudp ipt_MASQUERADE nf_nat_masquerade_ipv4 xt_comment xt_mark iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 iptable_filter xt_conntrack nf_nat nf_conntrack overlay sunrpc crc32_pclmul ghash_clmulni_intel pcbc mousedev aesni_intel psmouse evdev aes_x86_64 crypto_simd glue_helper pcc_cpufreq button cryptd ena ip_tables x_tables xfs libcrc32c nvme crc32c_intel nvme_core ipv6 crc_ccitt autofs4
kernel: CPU: 58 PID: 707658 Comm: kworker/u146:7 Tainted: G             L  4.14.165-133.209.amzn2.x86_64 #1
kernel: Hardware name: Amazon EC2 c5.18xlarge/, BIOS 1.0 10/16/2017
kernel: Workqueue: writeback wb_workfn (flush-259:0)
kernel: task: ffff8893fefa0000 task.stack: ffffc9002daec000
kernel: RIP: 0010:__list_del_entry_valid+0x28/0x90
kernel: RSP: 0018:ffffc9002daefcc0 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff10
kernel: RAX: ffff88916d19b470 RBX: ffffc9002daefce8 RCX: dead000000000200
kernel: RDX: ffff88804b1f36c8 RSI: ffff888013237e08 RDI: ffff888013237e08
kernel: RBP: ffff88916d19b470 R08: ffff889488d1eb48 R09: 0000000180400037
kernel: R10: ffffc9002daefe10 R11: 0000000000000000 R12: ffff88916d608800
kernel: R13: ffff888013237e08 R14: ffffc9002daefd78 R15: ffff889488d1eb48
kernel: FS:  0000000000000000(0000) GS:ffff88a371380000(0000) knlGS:0000000000000000
kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
kernel: CR2: 000010923314f000 CR3: 000000000200a002 CR4: 00000000007606e0
kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
kernel: PKRU: 55555554
kernel: Call Trace:
kernel: move_expired_inodes+0x6a/0x230
kernel: queue_io+0x61/0xf0
kernel: wb_writeback+0x258/0x300
kernel: ? wb_workfn+0xdf/0x370
kernel: ? __local_bh_enable_ip+0x6c/0x70
kernel: wb_workfn+0xdf/0x370
kernel: ? __switch_to_asm+0x41/0x70
kernel: ? __switch_to_asm+0x35/0x70
kernel: process_one_work+0x17b/0x380
kernel: worker_thread+0x2e/0x390
kernel: ? process_one_work+0x380/0x380
kernel: kthread+0x11a/0x130
kernel: ? kthread_create_on_node+0x70/0x70
kernel: ret_from_fork+0x35/0x40

Ideally with the change https://github.com/awslabs/amazon-eks-ami/pull/367 , kubelet should be having plenty of resources and if there are high resource consuming pods , it should just evict it rather than node getting crashed.

I digged into the customizations in detail and following are the customizations done for the AMI used in environment:

Customizations :

Docker daemon related

1a. Docker env
docker.env is used

            # The max number of open files for the daemon itself, and all
            # running containers.  The default value of 1048576 mirrors the value
            # used by the systemd service unit.
            DAEMON_MAXFILES=1048576

            # Additional startup options for the Docker daemon, for example:
            # OPTIONS="--ip-forward=true --iptables=true"
            # By default we limit the number of open files per container
            # Options are moved to docker-daemon.json
            #OPTIONS="--default-ulimit nofile=262144:1048576 --max-concurrent-downloads=100 --max-concurrent-uploads=100 --iptables=false"

            # How many seconds the sysvinit script waits for the pidfile to appear
            # when starting the daemon.
            DAEMON_PIDFILE_TIMEOUT=10

1b. docker daemon json
Default ulimits are changed and iptables is also set as false

            {
              "bridge": "none",
              "log-driver": "json-file",
              "log-opts": {
                "max-size": "10m",
                "max-file": "10"
              },
              "live-restore": true,
              "iptables": false,
              "max-concurrent-downloads": 100,
              "max-concurrent-uploads": 100,
              "default-ulimits": {
                "nofile": {
                  "Name": "nofile",
                  "Hard": 1048576,
                  "Soft": 262144
                }
              }
            }

System customizations:

2a. 20-nproc.conf
Limit user process to avoid fork bombing

            # Default limit for number of user's processes to prevent
            # accidental fork bombs.
            # See rhbz #432903 for reasoning.

            *          soft    nproc     3934939
            root       soft    nproc     unlimited

2b. sysctl.conf

            # Filesystem

            # Maximum number of allowable concurrent requests
            fs.aio-max-nr = 1048576

            # 1M max_user_watches takes extra 1Gb of kernel memory per real UID
            fs.inotify.max_user_watches = 1048576
            fs.inotify.max_user_instances = 2048


            # Kernel

            # Prevents Docker from crashing with:
            # > runtime/cgo: pthread_create failed: Resource temporarily unavailable
            kernel.pid_max = 1048576


            # Network

            # Max number of packets queued when the interface receives packets faster than
            # kernel can process them. Default is 1000
            net.core.netdev_max_backlog = 5000

            # Max rx/tx buffer sizes. Default 212k sounds too small for our 10g links, but
            # setting some very high numbers may have nasty consequences too
            net.core.rmem_max = 8388608
            net.core.wmem_max = 8388608

            # Threshold levels for ARP cache increased after neighbor table overflowed on DL1
            net.ipv4.neigh.default.gc_thresh1 = 4096
            net.ipv4.neigh.default.gc_thresh2 = 8192
            net.ipv4.neigh.default.gc_thresh3 = 8192

            # Number of memory-mapped areas per process used by elasticsearch and other
            # software that uses mmap
            vm.max_map_count = 262144

2c. systemd.conf
[Manager]
# Cgroup controllers here are joined to make system.slice appear in the common
# cgroup heirarchy. This way kubelet is able to use "system.slice" as
# --system-reserved to isolate system resources from pod resources
JoinControllers=cpu,cpuacct,cpuset,net_cls,net_prio,hugetlb,memory

Kubelet customizations

    Following is the kubelet output with ps     
    Eviction and system reserved option might be removed as its set in default.

/usr/bin/kubelet --cloud-provider aws --config /etc/kubernetes/kubelet/kubelet-config.json --kubeconfig /var/lib/kubelet/kubeconfig --container-runtime docker --read-only-port=10255 --network-plugin cni --node-ip=10.77.94.123 --pod-infra-container-image=602401143452.dkr.ecr.us-east-1.amazonaws.com/eks/pause-amd64:3.1 --runtime-cgroups=/systemd/system.slice --kubelet-cgroups=/systemd/system.slice --kube-api-qps=30 --kube-api-burst=50 --event-qps=30 --event-burst=50 --registry-qps=0 --enforce-node-allocatable=pods --eviction-hard=imagefs.available<15%,memory.available<5%,nodefs.available<10%,nodefs.inodesFree<5% --serialize-image-pulls=false --v=3 --pod-max-pids=8192 --node-labels=node-role.kubernetes.io/spot-worker --resolv-conf=/etc/resolv.kubelet

/usr/bin/kubelet --cloud-provider aws --config /etc/kubernetes/kubelet/kubelet-config.json --kubeconfig /var/lib/kubelet/kubeconfig --container-runtime docker --read-only-port=10255 --network-plugin cni --node-ip=10.77.94.123 --pod-infra-container-image=602401143452.dkr.ecr.us-east-1.amazonaws.com/eks/pause-amd64:3.1 --eviction-hard=imagefs.available<15%,memory.available<5%,nodefs.available<10%,nodefs.inodesFree<5% --serialize-image-pulls=false --v=3 --pod-max-pids=8192 --resolv-conf=/etc/resolv.kubelet

resolv.kubelet is following
/usr/bin/grep -v "^search " /etc/resolv.conf > /etc/resolv.kubelet

EDIT: Edited this post after removing some customization

cshivashankar on 3 May 2020

same here, subscribe

edubacco on 22 May 2020

We had the same problem upgrading our worker nodes to Amazon EKS 1.15 AMI. We tried:

amazon-eks-node-1.15-v20200507
amazon-eks-node-1.15-v20200423

and both had the same problem.

We have pods with initContainers copying about 1Gb of small files (WP install), and during the copy, in the Init phase, the worker nodes hang, becoming completely unresponsive.

Syslog on the worker node reports:

[  288.053638] watchdog: BUG: soft lockup - CPU#5 stuck for 23s! [kworker/u16:2:62]
[  288.059141] Modules linked in: rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver nfs lockd grace fscache veth iptable_mangle xt_connmark nf_conntrack_netlink nfnetlink xt_statistic xt_nat ipt_REJECT nf_reject_ipv4 xt_tcpudp ip_vs_sh ip_vs_wrr ip_vs_rr ip_vs nf_defrag_ipv6 ipt_MASQUERADE nf_nat_masquerade_ipv4 xt_comment xt_mark iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 xt_addrtype iptable_filter xt_conntrack nf_nat nf_conntrack br_netfilter bridge stp llc overlay sunrpc crc32_pclmul ghash_clmulni_intel pcbc mousedev aesni_intel aes_x86_64 crypto_simd evdev glue_helper psmouse cryptd button ena ip_tables x_tables xfs libcrc32c nvme crc32c_intel nvme_core ipv6 crc_ccitt autofs4
[  288.185290] CPU: 5 PID: 62 Comm: kworker/u16:2 Tainted: G             L  4.14.177-139.253.amzn2.x86_64 #1
[  288.191527] Hardware name: Amazon EC2 m5.2xlarge/, BIOS 1.0 10/16/2017
[  288.195344] Workqueue: writeback wb_workfn (flush-259:0)
[  288.198708] task: ffff888184670000 task.stack: ffffc90003360000
[  288.202280] RIP: 0010:move_expired_inodes+0xff/0x230
[  288.205542] RSP: 0018:ffffc90003363cc8 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff10
[  288.211042] RAX: 00000000ffffa056 RBX: ffffc90003363ce8 RCX: dead000000000200
[  288.215031] RDX: 0000000000000000 RSI: ffffc90003363ce8 RDI: ffff8887068963c8
[  288.219040] RBP: ffff888802273c70 R08: ffff888706896008 R09: 0000000100400010
[  288.223047] R10: ffffc90003363e10 R11: 0000000000025400 R12: ffff8888227f6800
[  288.227062] R13: ffff888706896788 R14: ffffc90003363d78 R15: ffff888706896008
[  288.231071] FS:  0000000000000000(0000) GS:ffff888822740000(0000) knlGS:0000000000000000
[  288.236761] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  288.240282] CR2: 00007f5b703af570 CR3: 000000000200a005 CR4: 00000000007606e0
[  288.244306] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  288.248328] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  288.252351] PKRU: 55555554
[  288.254821] Call Trace:
[  288.257178]  queue_io+0x61/0xf0
[  288.259798]  wb_writeback+0x258/0x300
[  288.262600]  ? wb_workfn+0xdf/0x370
[  288.265323]  ? __local_bh_enable_ip+0x6c/0x70
[  288.268370]  wb_workfn+0xdf/0x370
[  288.271040]  ? __switch_to_asm+0x41/0x70
[  288.273944]  ? __switch_to_asm+0x35/0x70
[  288.276845]  process_one_work+0x17b/0x380
[  288.279728]  worker_thread+0x2e/0x390
[  288.282509]  ? process_one_work+0x380/0x380
[  288.285482]  kthread+0x11a/0x130
[  288.288134]  ? kthread_create_on_node+0x70/0x70
[  288.291201]  ret_from_fork+0x35/0x40
[  288.293964] Code: b9 01 00 00 00 0f 44 4c 24 04 89 4c 24 04 49 89 c4 48 8b 45 00 48 39 c5 74 1a 4d 85 f6 4c 8b 6d 08 0f 84 67 ff ff ff 49 8b 45 e0 <49> 39 06 0f 89 5a ff ff ff 8b 44 24 04 85 c0 75 51 48 8b 44 24 
[  293.673669] ena 0000:00:05.0 eth0: Found a Tx that wasn't completed on time, qid 0, index 219.
[  293.679790] ena 0000:00:05.0 eth0: Found a Tx that wasn't completed on time, qid 0, index 220.

As workaround, we took the offical Ubuntu EKS 1.15 image ami-0f54d80ab3d460266, we added in it the nfs-common package to manage the EFS and we rebuilt a new custom AMI from it.

Note: Using kiam, we had to change the CA certificate path, because the location in Ubuntu is different from the one in AmazonLinux image.

colandre on 22 May 2020

👍3

@colandre Do you use stock AMI recommended by AWS or do you bake the AMI, if so what all customizations are you using?

It looks like the issue might be arising due to high resource utilization.
It's still not clear for me on why is this happening even when kubelet and all components like docker daemon have resource restrictions set. How can they overload system and cause kernel to panic.
Maybe someone from amazon can give a clear picture.

cshivashankar on 22 May 2020

@cshivashankar , I used stock Amazon AMIs:

amazon-eks-node-1.15-v20200507 - ami-023736532608ff45e
amazon-eks-node-1.15-v20200423 - ami-02955144c3a2cb6a1

no customizations.
I tried also to force kubeReserved and systemReserved in eksctl configuration to a higher limits compared to the auto-computed one by eksctl (0.19 and above), with no luck.
The suggested reservations for my instance type is 300m for the CPU and 300Mi for the memory.
I tried 1 core and 1Gb.
E.g.

...
kubeletExtraConfig:
        kubeReserved:
            cpu: "1024m"
            memory: "1Gi"
            ephemeral-storage: "1Gi"
        kubeReservedCgroup: "/kube-reserved"
        systemReserved:
            cpu: "1024m"
            memory: "1Gi"
            ephemeral-storage: "1Gi"
        evictionHard:
            memory.available:  "200Mi"
            nodefs.available: "10%"
...

colandre on 22 May 2020

@colandre Did you reach out to AWS support? Any inputs from them? I guess this thread has little visibility as it was created some days back. As per AWS, there should not be any issues if stock AMI is being used. It's definitely worth following up with AWS. Even I am curious about the solution to this problem

cshivashankar on 24 May 2020

@cshivashankar , unfortunately we do not have the Business Plan, so tech issues cannot be opened.

colandre on 25 May 2020

@colandre I think only way to get attention for this thread is to tag collaborator or contributor of this repo :)

cshivashankar on 25 May 2020

We're cautiously optimistic that upgrading our CNI plugin to 1.6.1 has resolved the issue for us. HTH

eeeschwartz on 28 May 2020

I work with @eeeschwartz . We now no longer think that the CNI upgrade change fixed this for us. What did fix it, was switching to instances with SSD drives such as r5d.2xlarge, and using that SSD drive for /var/lib/docker as suggested at https://github.com/awslabs/amazon-eks-ami/issues/349

Our actual experience with managing that filesystem was a bit different than suggested in that link. We found that dockerd needs to be stopped/started as part of the userdata script, even though we placed our code fragment in the "pre-userdata", i.e. as the very first steps. The following appears to be working for us:

if ( lsblk | fgrep -q nvme1n1 ); then
   mkfs.ext4 /dev/nvme1n1
   systemctl stop docker
   mkdir -p /var/lib/docker
   mount /dev/nvme1n1 /var/lib/docker
   chmod 711 /var/lib/docker
   systemctl start docker
fi

jae-63 on 28 May 2020

@jae-63 Moving docker daemon to nvme should ideally provide better performance and IO. Based on your experience of issue , did you see any co-relation to the issue and IOPS of volumes? Did you face any issues with EBS volume of very high IOPS.
Trying to understand why the soft lockup issue is arising, ideally docker running on EBS volume should work well.

cshivashankar on 28 May 2020

@cshivashankar for cost reasons [or our perceptions of the costs], we didn't pursue IOPS-provisioned EBS volumes, so I don't have any data to provide. I.e. we were previously just using vanilla 'gp2' drives.

I think that one could use IOPS-provisioned (i.e. "io1") drives instead of following our present solution. That would be a bit simpler.

Ephemeral SSDs associated with ephemeral instance like our use-case is a nice match. It seems likely that our (new) SSD drives are overprovisioned w.r.t size, in light of the available CPU/RAM/SSD size ratios. Other users might use more or less disk than us.

BTW we down-sized the root EBS partition to 20GB but even 10GB would probably be sufficient.

jae-63 on 28 May 2020

👍1

Hi @jae-63 Thanks for the info.Any easy ways/instructions for replicating this issue?

Hi @Jeffwan Do you see any potential bug or limitation which is causing these soft lockup issues. It looks like more people are facing these soft lockup issues and some of them are facing it in plain stock AMI which is recommended by AWS. It would be great to know your opinion on what might be causing these issues.

cshivashankar on 29 May 2020

@cshivashankar I don't see an easy way to reproduce this. The two affected clusters are mostly used for code building and deployment (primarily the former) using self-hosted Gitlab. As you may know, in ".gitlab-ci.yml" files, one invokes lots of different containers for a brief period of time, e.g. corresponding to building a Docker container. We recently started using the caching capabilities of the 'kaniko-project' https://cloud.google.com/cloud-build/docs/kaniko-cache for many of our builds.
I wonder whether that caching could place a heavy disk I/O load on EKS.

I'm pretty sure these are stock AMIs we're using. One cluster is still running EKS 1.15 and the other is EKS 1.16. They are 'ami-065418523a44331e5' and 'ami-0809659d79ce80260' respectively, in us-west-2.

We did open an AWS ticket for this lockup issue a few weeks ago, but not much was accomplished on it, and it's now closed. I don't know whether it's considered OK to post an AWS ticket number here, or perhaps there's a way for us to communicate privately. Perhaps you'd find some clues there.

In principle I'd be willing to revert to using regular 'r5' instances for a few hours (AFTER HOURS) rather than the 'r5d' ones we're currently using. That should reproduce the problem although the load is likely to be much lighter than during the daytime, when our developers are actively using Gitlab. In our experience we continued to observe these lockups after hours. But you'd need to tell me in advance, in detail, what diagnostics to try to collect.

jae-63 on 29 May 2020

Hi, @jae-63 Even my initial analysis pointed to high IOPS. I did try to simulate the error by subjecting node to high CPU, IOPS but somehow the soft lockup issue doesn't get reproduced in the dev environment. So it's becoming quite tricky to understand what's causing this soft lockup.
Earlier I was using following qps flags with kubelet for faster rate of communication with control plane
--kube-api-qps=30 --kube-api-burst=50 --event-qps=30 --event-burst=50 --registry-qps=0. After removing these flags , issues got reduced a lot but not completely eliminated. We too use Jenkins, so there might be some co-relation regarding the activities.

I had opened an AWS ticket and working actively with engineer and lack of reproduction steps has become a big hurdle. I am not from amazon, so I don't know if it's ok to share the ticket number, I can check and confirm.

Main diagnostics that can help is kernel crash dump, logs collected from log collector script, and system metrics maybe using SAR or similar tools.

cshivashankar on 30 May 2020

Hi @cshivashankar . Sorry I had misunderstood ... I thought you were AWS staff and were seeking customer help to resolve this for the larger community. In light of the fact that you, like me, don't work for AWS I'm going to excuse myself from further activity here, because I don't think I have much to add beyond the workaround I have already provided.

jae-63 on 3 Jun 2020

Can those of you experiencing this issue please try the following on your nodes, reboot, and see if you're still experiencing the issue?

sudo amazon-linux-extras install kernel-ng
sudo reboot

otterley on 12 Jun 2020

Alternatively, for those of you experiencing this issue, if you switch to c4/r4/m4 instances instead of c5/r5/m5, does it make a difference?

otterley on 12 Jun 2020

encing this issue please try the following on your nodes, reboot, and see if you're still experiencing the issue?

Can you please provide more details on how this solves the issue. I am ok to try this if this solves any known issue or bug.