6 intriguing system bugs in operating Kubernetes [and their solutions]

Over the years of operating Kubernetes in production, we have accumulated quite a few interesting stories about how bugs in various system components led to unpleasant or perplexing consequences that affected the operation of containers and pods. In this article, we have compiled some of the most frequent or intriguing ones. Even if you never encounter such situations, reading about these brief detective stories—especially from 'first-hand' sources—is always intriguing, isn't it?

Story 1. Supercronic and Docker Hanging

On one of the clusters, we periodically experienced a 'hanging' Docker, which hindered the normal functioning of the cluster. At the same time, the Docker logs revealed the following

level=error msg="containerd: start init process" error="exit status 2: "runtime/cgo: pthread_create failed: No space left on device
SIGABRT: abort
PC=0x7f31b811a428 m=0

goroutine 0 [idle]:

goroutine 1 [running]:
runtime.systemstack_switch() /usr/local/go/src/runtime/asm_amd64.s:252 fp=0xc420026768 sp=0xc420026760
runtime.main() /usr/local/go/src/runtime/proc.go:127 +0x6c fp=0xc4200267c0 sp=0xc420026768
runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc4200267c8 sp=0xc4200267c0

goroutine 17 [syscall, locked to thread]:
runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:2086 +0x1

…

In this error, we are most interested in the message: pthread_create failed: No space left on device. A quick examination the documentation revealed that Docker cannot fork the process, which is why it periodically 'hung'.

The monitoring reflects the following picture:

A similar situation is observed on other nodes:

On these same nodes, we see:

root@kube-node-1 ~ # ps auxfww | grep curl -c
19782
root@kube-node-1 ~ # ps auxfww | grep curl | head
root     16688  0.0  0.0      0     0 ?        Z    Feb06   0:00      |       _ [curl] 
root     17398  0.0  0.0      0     0 ?        Z    Feb06   0:00      |       _ [curl] 
root     16852  0.0  0.0      0     0 ?        Z    Feb06   0:00      |       _ [curl] 
root      9473  0.0  0.0      0     0 ?        Z    Feb06   0:00      |       _ [curl] 
root      4664  0.0  0.0      0     0 ?        Z    Feb06   0:00      |       _ [curl] 
root     30571  0.0  0.0      0     0 ?        Z    Feb06   0:00      |       _ [curl] 
root     24113  0.0  0.0      0     0 ?        Z    Feb06   0:00      |       _ [curl] 
root     16475  0.0  0.0      0     0 ?        Z    Feb06   0:00      |       _ [curl] 
root      7176  0.0  0.0      0     0 ?        Z    Feb06   0:00      |       _ [curl] 
root      1090  0.0  0.0      0     0 ?        Z    Feb06   0:00      |       _ [curl]

It turned out that this behavior was a consequence of the pod working with supercronic (a Go utility that we use to run cron jobs in pods):

 _ docker-containerd-shim 833b60bb9ff4c669bb413b898a5fd142a57a21695e5dc42684235df907825567 /var/run/docker/libcontainerd/833b60bb9ff4c669bb413b898a5fd142a57a21695e5dc42684235df907825567 docker-runc
|   _ /usr/local/bin/supercronic -json /crontabs/cron
|       _ /usr/bin/newrelic-daemon --agent --pidfile /var/run/newrelic-daemon.pid --logfile /dev/stderr --port /run/newrelic.sock --tls --define utilization.detect_aws=true --define utilization.detect_azure=true --define utilization.detect_gcp=true --define utilization.detect_pcf=true --define utilization.detect_docker=true
|       |   _ /usr/bin/newrelic-daemon --agent --pidfile /var/run/newrelic-daemon.pid --logfile /dev/stderr --port /run/newrelic.sock --tls --define utilization.detect_aws=true --define utilization.detect_azure=true --define utilization.detect_gcp=true --define utilization.detect_pcf=true --define utilization.detect_docker=true -no-pidfile
|       _ [newrelic-daemon] 
|       _ [curl] 
|       _ [curl] 
|       _ [curl] 
…

The problem is as follows: when a task is started in supercronic, the process spawned by it cannot terminate correctly, turning into a zombie.

Note: To be precise, processes are spawned by cron tasks, but supercronic is not an init system and cannot 'adopt' the processes spawned by its children. When SIGHUP or SIGTERM signals are generated, they are not passed to the spawned processes, which means that the child processes do not terminate, remaining in a zombie state. More details on this can be found, for instance, in such an article.

There are a couple of ways to solve the issues:

1. As a temporary workaround — increase the number of PIDs in the system at a given time:

          /proc/sys/kernel/pid_max (since Linux 2.5.34)
                 This file specifies the value at which PIDs wrap around (i.e., the value in this file is one greater than the maximum PID).  PIDs greater than this  value  are  not  allo‐
                 cated;  thus, the value in this file also acts as a system-wide limit on the total number of processes and threads.  The default value for this file, 32768, results in the
                 same range of PIDs as on earlier kernels

2. Or start tasks in supercronic not directly, but using the same tini, which can correctly terminate processes and not spawn zombies.

History 2. Zombies when removing cgroup

Kubelet started consuming a lot of CPU:

Nobody likes this, so we armed ourselves perf and began to investigate the problem. The investigation results were as follows:

• Kubelet spends more than a third of its CPU time pulling memory data from all cgroups:

  

• In the kernel developers mailing list, you can find a discussion of the issue. In short, it boils down to the fact that various tmpfs files and other similar things are not completely removed from the system when removing cgroup — so-called memcg zombies. Sooner or later, they will be removed from the page cache; however, there is plenty of memory on the server, and the kernel doesn't see any point in spending time removing them. Therefore, they continue to accumulate. Why does this even happen? This is a server with cron jobs that constantly creates new jobs, bringing new pods with them. Thus, new cgroups are created for the containers within them, which are soon deleted.
• Why does cAdvisor in kubelet take so much time? This can easily be seen by simply executing time cat /sys/fs/cgroup/memory/memory.stat. If the operation takes 0.01 seconds on a healthy machine, then on the problematic cron02 it takes 1.2 seconds. The reason is that cAdvisor, which reads data from sysfs very slowly, tries to account for the memory used in the zombie cgroups.
• To forcefully remove zombies, we tried cleaning the caches as recommended in LKML: sync; echo 3 > /proc/sys/vm/drop_caches, — but the kernel turned out to be more complicated and hung the machine.

What to do? The problem can be fixed (the commit, for a description see the release note) by updating the Linux kernel to version 4.16.

Story 3. Systemd and its mount

Once again, kubelet consumes too many resources on some nodes, but this time — memory:

It turned out that there is a problem in systemd used in Ubuntu 16.04, which arises when managing mounts created for connecting subPath from ConfigMaps or secrets. After the pod has finished its work, the systemd service and its auxiliary mount remain in the system. Over time, they accumulate in large numbers. There are even issues on this topic:

1. kops #5916;
2. kubernetes #57345.

… in the latest of which references a PR in systemd: #7811 (issue in systemd — #7798).

The problem is no longer present in Ubuntu 18.04, but if you want to continue using Ubuntu 16.04, our workaround on this topic may be useful to you.

So, we created the following DaemonSet:

---
apiVersion: extensions/v1beta1
kind: DaemonSet
metadata:
  labels:
    app: systemd-slices-cleaner
  name: systemd-slices-cleaner
  namespace: kube-system
spec:
  updateStrategy:
    type: RollingUpdate
  selector:
    matchLabels:
      app: systemd-slices-cleaner
  template:
    metadata:
      labels:
        app: systemd-slices-cleaner
    spec:
      containers:
      - command:
        - /usr/local/bin/supercronic
        - -json
        - /app/crontab
        Image: private-registry.org/systemd-slices-cleaner/systemd-slices-cleaner:v0.1.0
        imagePullPolicy: Always
        name: systemd-slices-cleaner
        resources: {}
        securityContext:
          privileged: true
        volumeMounts:
        - name: systemd
          mountPath: /run/systemd/private
        - name: docker
          mountPath: /run/docker.sock
        - name: systemd-etc
          mountPath: /etc/systemd
        - name: systemd-run
          mountPath: /run/systemd/system/
        - name: lsb-release
          mountPath: /etc/lsb-release-host
      imagePullSecrets:
      - name: antiopa-registry
      priorityClassName: cluster-low
      tolerations:
      - operator: Exists
      volumes:
      - name: systemd
        hostPath:
          path: /run/systemd/private
      - name: docker
        hostPath:
          path: /run/docker.sock
      - name: systemd-etc
        hostPath:
          path: /etc/systemd
      - name: systemd-run
        hostPath:
          path: /run/systemd/system/
      - name: lsb-release
        hostPath:
          path: /etc/lsb-release

… and it uses the following script:

#!/bin/bash

# we will work only on xenial
hostrelease="/etc/lsb-release-host"
test -f ${hostrelease} && grep xenial ${hostrelease} > /dev/null || exit 0

# sleeping max 30 minutes to dispense load on kube-nodes
sleep $((RANDOM % 1800))

stoppedCount=0
# counting actual subpath units in systemd
countBefore=$(systemctl list-units | grep subpath | grep "run-" | wc -l)
# let's go check each unit
for unit in $(systemctl list-units | grep subpath | grep "run-" | awk '{print $1}'); do
  # finding description file for unit (to find out docker container, who born this unit)
  DropFile=$(systemctl status ${unit} | grep Drop | awk -F': ' '{print $2}')
  # reading uuid for docker container from description file
  DockerContainerId=$(cat ${DropFile}/50-Description.conf | awk '{print $5}' | cut -d/ -f6)
  # checking container status (running or not)
  checkFlag=$(docker ps | grep -c ${DockerContainerId})
  # if container not running, we will stop unit
  if [[ ${checkFlag} -eq 0 ]]; then
    echo "Stopping unit ${unit}"
    # stoping unit in action
    systemctl stop $unit
    # just counter for logs
    ((stoppedCount++))
    # logging current progress
    echo "Stopped ${stoppedCount} systemd units out of ${countBefore}"
  fi
done

… and it runs every 5 minutes using the previously mentioned supercronic. Its Dockerfile looks like this:

FROM ubuntu:16.04
COPY rootfs /
WORKDIR /app
RUN apt-get update && 
    apt-get upgrade -y && 
    apt-get install -y gnupg curl apt-transport-https software-properties-common wget
RUN add-apt-repository "deb [arch=amd64] https://download.docker.com/linux/ubuntu xenial stable" && 
    curl -fsSL https://download.docker.com/linux/ubuntu/gpg | apt-key add - && 
    apt-get update && 
    apt-get install -y docker-ce=17.03.0*
RUN wget https://github.com/aptible/supercronic/releases/download/v0.1.6/supercronic-linux-amd64 -O 
    /usr/local/bin/supercronic && chmod +x /usr/local/bin/supercronic
ENTRYPOINT ["/bin/bash", "-c", "/usr/local/bin/supercronic -json /app/crontab"]

Story 4. Concurrency in pod scheduling

It was noted that: if a pod is deployed on a node and its image takes a long time to download, another pod that "lands" on the same node simply does not start pulling the image of the new pod.Instead, it waits for the previous pod's image to finish pulling. As a result, a pod that has already been scheduled and whose image could be downloaded in just a minute gets stuck in the containerCreating.

In the events, there will be something like the following:

Normal  Pulling    8m    kubelet, ip-10-241-44-128.ap-northeast-1.compute.internal  pulling image "registry.example.com/infra/openvpn/openvpn:master"

This means that a single image from a slow registry can block the deployment on the node.

Unfortunately, there are not many solutions to this issue:

1. Try to use your Docker Registry directly in the cluster or with the cluster (for example, GitLab Registry, Nexus, etc.);
2. Utilize tools such as kraken.

History 5. Node hanging due to lack of memory

During the operation of various applications, we also encountered a situation where a node became completely unavailable: it does not respond to SSH, all monitoring daemons drop off, and the logs show nothing (or almost nothing) abnormal.

I'll illustrate with images using an example of one node where MongoDB was functioning.

This is what atop looks like up to crashes:

And this is how it looks — after crashes:

Monitoring also shows a sharp spike when the node becomes unavailable:

Thus, the screenshots indicate that:

1. The machine's RAM is nearly exhausted;
2. There is a sudden spike in RAM usage, after which access to the entire machine is abruptly cut off;
3. A large task arrives for Mongo that causes the database process to use more memory and actively read from the disk.

It turns out that when free memory runs out in Linux (when memory pressure occurs) and there is no swap, up to the arrival of the OOM killer may lead to an equilibrium between pushing pages into page cache and writing them back to disk. This is handled by kswapd, which bravely frees as many memory pages as possible for subsequent allocation.

Unfortunately, under high I/O load combined with a low amount of free memory, kswapd becomes the bottleneck of the entire system, because it is tied to all memory page allocations (page faults) in the system. This can last a very long time if processes do not want to use more memory and get stuck on the edge of the OOM-killer abyss.

The question arises: why does the OOM killer come so late? In its current iteration, the OOM killer is extremely foolish: it will only kill a process when an attempt to allocate a memory page fails, i.e., if the page fault fails. This does not happen for a long time because kswapd is bravely freeing memory pages by flushing the page cache (essentially all disk I/O in the system) back to disk. For more details, including the steps necessary to resolve such issues in the kernel, you can read here.

This behavior should improve with Linux kernel 4.6+.

History 6. Pods are stuck in Pending state

In some clusters where a substantial number of pods are operational, we began to notice that many of them remain 'stuck' in state Here are possible reasons (assuming that the scheduler is functioning normally):, even though the Docker containers are already running on nodes and can be manually accessed.

However, there's nothing wrong with of the PVC object: :

  Type    Reason                  Age                From                     Message
  ----    ------                  ----               ----                     -------
  Normal  Scheduled               1m                 default-scheduler        Successfully assigned sphinx-0 to ss-dev-kub07
  Normal  SuccessfulAttachVolume  1m                 attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-6aaad34f-ad10-11e8-a44c-52540035a73b"
  Normal  SuccessfulMountVolume   1m                 kubelet, ss-dev-kub07    MountVolume.SetUp succeeded for volume "sphinx-config"
  Normal  SuccessfulMountVolume   1m                 kubelet, ss-dev-kub07    MountVolume.SetUp succeeded for volume "default-token-fzcsf"
  Normal  SuccessfulMountVolume   49s (x2 over 51s)  kubelet, ss-dev-kub07    MountVolume.SetUp succeeded for volume "pvc-6aaad34f-ad10-11e8-a44c-52540035a73b"
  Normal  Pulled                  43s                kubelet, ss-dev-kub07    Container image "registry.example.com/infra/sphinx-exporter/sphinx-indexer:v1" already present on machine
  Normal  Created                 43s                kubelet, ss-dev-kub07    Created container
  Normal  Started                 43s                kubelet, ss-dev-kub07    Started container
  Normal  Pulled                  43s                kubelet, ss-dev-kub07    Container image "registry.example.com/infra/sphinx/sphinx:v1" already present on machine
  Normal  Created                 42s                kubelet, ss-dev-kub07    Created container
  Normal  Started                 42s                kubelet, ss-dev-kub07    Started container

Upon investigation, we hypothesized that kubelet simply can't send all the information about the status of the pods to the API server in time, regarding liveness/readiness probes.

After examining the help, we found the following parameters:

--kube-api-qps - QPS to use while talking with kubernetes apiserver (default 5)
--kube-api-burst  - Burst to use while talking with kubernetes apiserver (default 10) 
--event-qps - If > 0, limit event creations per second to this value. If 0, unlimited. (default 5)
--event-burst - Maximum size of a bursty event records, temporarily allows event records to burst to this number, while still not exceeding event-qps. Only used if --event-qps > 0 (default 10) 
--registry-qps - If > 0, limit registry pull QPS to this value.
--registry-burst - Maximum size of bursty pulls, temporarily allows pulls to burst to this number, while still not exceeding registry-qps. Only used if --registry-qps > 0 (default 10)

As you can see, the default values are quite small, and in 90% of cases they meet all needs... However, in our case, this was insufficient. Therefore, we set the following values:

--event-qps=30 --event-burst=40 --kube-api-burst=40 --kube-api-qps=30 --registry-qps=30 --registry-burst=40

... and restarted the kubelets, after which we saw the following pattern on the API server access graphs:

... and yes, everything started to fly!

P.S.

I would like to express my deep gratitude to the many engineers in our company for their help in bug collection and article preparation, especially to my colleague from our R&D team, Andrey Klimentyev (zuzzas).

P.P.S.

Also read in our blog:

• «The kubectl-debug plugin for debugging in Kubernetes pods».
• Kubernetes Tips & Tricks Cycle:
  • «Translation of resources running in a cluster under Helm 2 management»;
  • «On node allocation and loads on web applications»;
  • «Access to dev environments»;
  • «Accelerating the bootstrap of large databases».

Source: habr.com