CrashLoopBackOff on calico pods caused by loopback interface being down

[MridulS]

We run a Kubernetes cluster with calico and sporadically the cluster goes down (~once a month). The calico pod on one of
the nodes goes into perpetual CrashLoopBackOff state and the node's loopback interface is down (can't even ping itself).

One thing to note is that we run around ~200 pods in that node.

Expected Behavior

The cluster should be stable.

Current Behavior

ip address show lo output on the node

lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state DOWN group default qlen 1000

calicoctl node status on the node

$ sudo calicoctl node status
Calico process is not running.

Possible Solution

What we do to fix this is to run ip link set dev lo up manually enabling the loopback interface and restarting the pod.

Steps to Reproduce (for bugs)

The issue pops up sporadically.

Context

We have a guess that this has probably something to do with us running more than the limit of 110 pods on a node.

Your Environment

• Calico version 3.17.0
• Orchestrator version (e.g. kubernetes, mesos, rkt): kubernetes 1.19.4
• Operating System and version: Ubuntu 18.04.4 LTS (GNU/Linux 4.15.0-126-generic x86_64)
• Link to your project (optional): https://github.com/gesiscss/orc

[mgleung]

Hi @MridulS, thanks for bringing this to our attention.

Could I ask you to provide the pod logs for some of the pods that get stuck? Since we are suspecting that this is due to the large amount of pods on each node, could we also get the cpu and memory utilization on one of the nodes that gets stuck?

[MridulS]

@mgleung thanks for the response!

In terms of cpu/memory utilisation it's far far away from the node capacity. And (un)luckily this happened again a couple of hours back.

Output of kubectl describe pod calico-node-l2vjq -n kube-system -> https://pastebin.ubuntu.com/p/ddp87jbyDp/
The logs from the calico pod which is stuck in perpetual CrashLoopBackOff -> https://pastebin.ubuntu.com/p/NKskcwccrJ/

This was again solved by going to the node, forcing the loopback interface to go back up, and restarting the calico pod on the node.

[mgleung]

Hi @MridulS sorry for the late response.

I don't see anything out of the ordinary in the logs. It just looks like the CNI plugin is struggling since the loopback interface goes down. Out of curiosity does this happen after a node restart of some kind? I have seen a similar issue where a node restarting tells the container runtime to issue a delete against processes running the root network namespace which then could tell us to tear the loopback interface down in the past. In the past we've gotten around those issues with an updated container runtime, but maybe we need to look into some other safeguards as well. This is the (CRI-O) fix in the past that fixed the issue I've seen in the past: cri-o/cri-o#3097 .

On that note, do we know what container runtime and version we're using?

[MridulS]

@mgleung thanks for getting back on this!

Out of curiosity does this happen after a node restart of some kind?

Nope, this happens sporadically and we haven't been able to find a pattern or anything of that sort :/

do we know what container runtime and version we're using?

We use docker v19.03.11 as the container runtime.

Thanks!

[mgleung]

@MridulS Let me see if I can dig anything up on docker v19.03.11 though that might not be the issue here.

In the meantime, can I ask you to see what the CIDR block on the node with ~200 nodes looks like and maybe get the Calico IPAM data as well? I know you mentioned going above the 110 pod limit so I want to see how all the pods got valid IP addresses assigned to them.

[caseydavenport]

Liveness probe failed: calico/node is not ready: Felix is not live: Get "http://localhost:9099/liveness": context deadline exceeded

Yep, it looks to me like Felix is perfectly healthy from the logs, and that the liveness probe is failing because the kubelet can't reach felix over localhost.

You could try adjusting the probes to communicate over a different address on the node to remove the dependency on the loopback, but it's still weird. I would focus on trying to find out who is setting the lo interface down, since I think that is why calico is crashing (and not vice-versa)

[clementnuss]

@caseydavenport Yeah, I would also advocate to look in this direction.
I had the same issue on a node running SUSE Linux 15 and Kernel 4.12, and Docker 19.03.5
Calico liveness probe was failing, but the logs and behaviour were healthy (iptables rules were still updating for example).

In fact, any request to any port on the loopback address 127.0.0.1 was failing, and running tcpdump -i any port 9099 showed nothing when reaching out to 127.0.0.1. When reaching to another IP address of this node (e.g. 10.0.0.13) you would see traffic in tcpdump.

We need to find what could put the loopback device down 🧐 I am looking through the logs and will get back here if I find something else.

[MridulS]

@mgleung CIDR block on the 200 pods node:

PodCIDR:                      10.244.1.0/24
PodCIDRs:                     10.244.1.0/24

IPAM data at the moment

iuser@svko-ilcm03:~$ calicoctl ipam show
+----------+---------------+-----------+------------+--------------+
| GROUPING |     CIDR      | IPS TOTAL | IPS IN USE |   IPS FREE   |
+----------+---------------+-----------+------------+--------------+
| IP Pool  | 10.244.0.0/16 |     65536 | 170 (0%)   | 65366 (100%) |
+----------+---------------+-----------+------------+--------------+

@caseydavenport @clementnuss thanks for your comments!

I would focus on trying to find out who is setting the lo interface down, since I think that is why calico is crashing (and not vice-versa)

Would calico have logged this anywhere (if calico set in down)? or any other system log?

[lwr20]

Would calico have logged this anywhere (if calico set in down)? or any other system log?

Yes, it would have logged this in the pod log. @fasaxc is there any code in calico-node which might set the loopback interface down?

[fasaxc]

I can't think of anywhere in the product that we set an interface down (and I grepped the codebase for the relevant API call and got no hits); what makes you think that Calico set the interface down?

I recommend checking the system journal for the time that lo went down. Maybe the app that is doing that will emit some sort of log about it.

[fasaxc]

Do you run any host-networked pods apart from Calico or any apps on the hosts themselves that might do this?

[MridulS]

I recommend checking the system journal for the time that lo went down. Maybe the app that is doing that will emit some sort of log about it.

Looking around the logs, this is pretty much the only thing that shows up

Jan 31 02:46:38 spko-css-app03 systemd-networkd[1831]: lo: Link DOWN

Just before this the log also shows

Jan 31 02:46:38 spko-css-app03 kubelet[51843]: E0131 02:46:38.082386   51843 cni.go:387] Error deleting [pod_name]
from network calico/k8s-pod-network: Calico CNI timed out deleting device in netns /proc/22132/ns/net

I am not sure if this has anything to do with this particular issue but all over the logs for this node in the cluster I also see these repeatedly, similar to #3960

Jan 27 15:12:29 spko-css-app03 systemd-networkd[1831]: cali9fc2547026b: Link DOWN
Jan 27 15:12:29 spko-css-app03 systemd-networkd[1831]: cali9fc2547026b: Lost carrier
Jan 27 15:12:30 spko-css-app03 systemd-networkd[1831]: veth0767ff4: Lost carrier
Jan 27 15:12:30 spko-css-app03 systemd-networkd[1831]: veth0767ff4: Link DOWN
Jan 27 15:12:36 spko-css-app03 systemd-networkd[1831]: cali67e58869912: Link DOWN
Jan 27 15:12:36 spko-css-app03 systemd-networkd[1831]: cali67e58869912: Lost carrier
Jan 27 15:12:37 spko-css-app03 systemd-networkd[1831]: cali07f6888a02d: Link DOWN
Jan 27 15:12:37 spko-css-app03 systemd-networkd[1831]: cali07f6888a02d: Lost carrier
Jan 27 15:12:38 spko-css-app03 systemd-networkd[1831]: vethf323651: Link UP
Jan 27 15:12:38 spko-css-app03 systemd-networkd[1831]: cali2fff62b1e79: Link DOWN
Jan 27 15:12:38 spko-css-app03 systemd-networkd[1831]: cali2fff62b1e79: Lost carrier
Jan 27 15:12:39 spko-css-app03 systemd-networkd[1831]: cali88beb9eb3cc: Link UP
Jan 27 15:12:39 spko-css-app03 systemd-networkd[1831]: cali88beb9eb3cc: Gained carrier
Jan 27 15:12:42 spko-css-app03 systemd-networkd[1831]: calia0c5a214559: Link UP
Jan 27 15:12:42 spko-css-app03 systemd-networkd[1831]: calia0c5a214559: Gained carrier
Jan 27 15:12:43 spko-css-app03 systemd-networkd[1831]: cali259655496fd: Link DOWN
Jan 27 15:12:43 spko-css-app03 systemd-networkd[1831]: cali259655496fd: Lost carrier
Jan 27 15:12:43 spko-css-app03 systemd-networkd[1831]: vethf323651: Gained carrier

Do you run any host-networked pods apart from Calico or any apps on the hosts themselves that might do this?

There is coredns running, not other app should be doing the networking part.

[fasaxc]

This one looks a bit suspicious:

Jan 31 02:46:38 spko-css-app03 kubelet[51843]: E0131 02:46:38.082386   51843 cni.go:387] Error deleting [pod_name]
from network calico/k8s-pod-network: Calico CNI timed out deleting device in netns /proc/22132/ns/net

More than 5s to delete the pod's veth is quite a long time; perhaps a kernel bug and nelink operations are wedged?

These messages are normal as pods come and go; they're logged by the kernel when we create/delete the workload's veth.

Jan 27 15:12:42 spko-css-app03 systemd-networkd[1831]: calia0c5a214559: Link UP
Jan 27 15:12:42 spko-css-app03 systemd-networkd[1831]: calia0c5a214559: Gained carrier
Jan 27 15:12:43 spko-css-app03 systemd-networkd[1831]: cali259655496fd: Link DOWN
Jan 27 15:12:43 spko-css-app03 systemd-networkd[1831]: cali259655496fd: Lost carrier

This one doesn't use Calico's naming scheme:

Jan 27 15:12:43 spko-css-app03 systemd-networkd[1831]: vethf323651: Gained carrier

Do you also have another CNI running or other kinds of workloads (e.g. native docker containers running)?

[MridulS]

Thanks for the reply @fasaxc!

More than 5s to delete the pod's veth is quite a long time; perhaps a kernel bug and nelink operations are wedged?

I guess I can upgrade the machines [currently running Ubuntu 18.04.4 LTS (GNU/Linux 4.15.0-126-generic x86_64)]

Do you also have another CNI running or other kinds of workloads (e.g. native docker containers running)?

Calico is the only CNI we run and no docker container is running outside k8s. Looking a bit more at the logs it looks like the veth interface is attached with docker0. (These messages are emitted even when the cluster is working smoothly)

Jan 31 12:43:34 spko-css-app03 systemd-networkd[1831]: vethf079a74: Link DOWN
Jan 31 12:43:34 spko-css-app03 kernel: docker0: port 2(vethf079a74) entered disabled state
Jan 31 12:43:34 spko-css-app03 networkd-dispatcher[2096]: WARNING:Unknown index 427884 seen, reloading interface list
Jan 31 12:43:34 spko-css-app03 kernel: device vethf079a74 left promiscuous mode
Jan 31 12:43:34 spko-css-app03 kernel: docker0: port 2(vethf079a74) entered disabled state
Jan 31 12:43:34 spko-css-app03 containerd[2174]: time="2021-01-31T12:43:34.921022687+01:00" level=info msg="shim reaped" id=af601db7c533014e1fdbc1db335ad01ac2bbf91269ea57acb5e9f83103bda9dc
Jan 31 12:43:34 spko-css-app03 dockerd[2445]: time="2021-01-31T12:43:34.930724904+01:00" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Jan 31 12:43:34 spko-css-app03 systemd-udevd[62168]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 31 12:43:34 spko-css-app03 systemd-udevd[62168]: link_config: could not get ethtool features for vethac49877
Jan 31 12:43:34 spko-css-app03 systemd-udevd[62168]: Could not set offload features of vethac49877: No such device

Also for a sanity check, this is the the output for the kube-system namespace.

$ kubectl get all -n kube-system
NAME                                           READY   STATUS    RESTARTS   AGE
pod/calico-kube-controllers-5dc87d545c-br5tx   1/1     Running   0          57d
pod/calico-node-8k26n                          1/1     Running   0          57d
pod/calico-node-dzhcw                          1/1     Running   0          57d
pod/calico-node-zl9w6                          1/1     Running   0          2d22h
pod/coredns-f9fd979d6-4jjcz                    1/1     Running   0          57d
pod/coredns-f9fd979d6-q2rkk                    1/1     Running   0          57d
pod/etcd-svko-ilcm03                           1/1     Running   0          57d
pod/kube-apiserver-svko-ilcm03                 1/1     Running   0          57d
pod/kube-controller-manager-svko-ilcm03        1/1     Running   0          57d
pod/kube-proxy-cb6v6                           1/1     Running   0          57d
pod/kube-proxy-lhsfs                           1/1     Running   0          57d
pod/kube-proxy-w6mjr                           1/1     Running   0          57d
pod/kube-scheduler-svko-ilcm03                 1/1     Running   0          57d

NAME               TYPE        CLUSTER-IP   EXTERNAL-IP   PORT(S)                  AGE
service/kube-dns   ClusterIP   10.96.0.10   <none>        53/UDP,53/TCP,9153/TCP   57d

NAME                         DESIRED   CURRENT   READY   UP-TO-DATE   AVAILABLE   NODE SELECTOR            AGE
daemonset.apps/calico-node   3         3         3       3            3           kubernetes.io/os=linux   57d
daemonset.apps/kube-proxy    3         3         3       3            3           kubernetes.io/os=linux   57d

NAME                                      READY   UP-TO-DATE   AVAILABLE   AGE
deployment.apps/calico-kube-controllers   1/1     1            1           57d
deployment.apps/coredns                   2/2     2            2           57d

NAME                                                 DESIRED   CURRENT   READY   AGE
replicaset.apps/calico-kube-controllers-5dc87d545c   1         1         1       57d
replicaset.apps/coredns-f9fd979d6                    2         2         2       57d

[fasaxc]

Yes, I'd try updating kernel and docker; it's hard to see how Calico could set your lo interface down. I think having lo down will break Calico, for sure but I don't see how we can cause it unless there's a kernel bug.