6 bugs de sistema interessantes na operação do Kubernetes [e suas soluções]

Ao longo dos anos de uso do Kubernetes em produção, acumulamos várias histórias intrigantes sobre como bugs em diferentes componentes do sistema levaram a consequências desagradáveis e/ou confusas que afetaram o funcionamento de contêineres e pods. Neste artigo, reunimos algumas das situações mais recorrentes ou interessantes. Mesmo que você nunca tenha a sorte de enfrentar tais situações, ler sobre esses breves mistérios — especialmente 'de primeira mão' — é sempre fascinante, não é mesmo? ...

História 1. Supercronic e Docker travado

Em um de nossos clusters, occasionalmente enfrentávamos um Docker 'travado', o que prejudicava o funcionamento normal do cluster. Ao mesmo tempo, nos logs do Docker, era possível observar o seguinte

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

…

O que mais nos interessa nesta mensagem de erro é: pthread_create failed: No space left on device. Uma análise rápida documentação esclareceu que o Docker não consegue forkear um processo, o que ocasionalmente resultava em 'travamentos'.

No monitoramento da situação, a imagem correspondente é a seguinte:

Uma situação semelhante foi observada em outros nós:

Nos mesmos nós, observamos:

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]

Descobrimos que esse comportamento é consequência da utilização do pod com supercronic (uma ferramenta em Go que usamos para executar tarefas cron em 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] 
…

O problema é a seguinte: quando a tarefa é iniciada no supercronic, o processo gerado por ele não consegue terminar corretamente, transformando-se em zumbi.

Nota: Para ser mais preciso, os processos são gerados por tarefas cron, mas o supercronic não é um sistema init e não pode "adotar" os processos que seus filhos geraram. Sinais SIGHUP ou SIGTERM não são enviados para os processos filhos, resultando na não finalização dos processos filhos, permanecendo em estado de zumbi. Você pode ler mais sobre tudo isso, por exemplo, em este artigo.

Existem algumas formas de solucionar os problemas:

1. Como uma solução temporária — aumentar o número de PIDs no sistema ao mesmo tempo:

          /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. Ou então, iniciar as tarefas no supercronic não diretamente, mas com a ajuda do mesmo tini, que pode encerrar os processos corretamente e não gerar zumbis.

História 2. "Zumbis" ao excluir cgroup

O Kubelet começou a consumir muita CPU:

Isso não é agradável para ninguém, então nos armamos perf e começamos a investigar o problema. Os resultados da investigação foram os seguintes:

• O Kubelet gasta mais de um terço do tempo de CPU extraindo dados de memória de todos os cgroups:

  

• Na lista de discussão dos desenvolvedores do núcleo, você pode encontrar discussão sobre o problema. Resumindo, a essência se resume ao fato de que diferentes arquivos tmpfs e outras coisas semelhantes não são completamente removidos do sistema ao excluir cgroup — permanecem os chamados memcg zumbi. Tarde ou cedo, eles ainda serão removidos do cache da página, mas como há muita memória no servidor, o núcleo não vê sentido em gastar tempo removendo-os. Portanto, eles continuam se acumulando. Por que isso acontece? Este é um servidor com tarefas cron que continuamente cria novos jobs, e com eles — novos pods. Assim, para os contêineres, novas cgroups são criadas, que logo serão removidas.
• Por que o cAdvisor no kubelet está consumindo tanto tempo? Isso é fácil de ver realizando uma simples execução time cat /sys/fs/cgroup/memory/memory.stat. Se em uma máquina saudável a operação leva 0,01 segundos, na problemática cron02 leva 1,2 segundos. O problema é que o cAdvisor, que lê dados do sysfs muito lentamente, tenta contabilizar a memória usada e os cgroups zumbis.
• Para forçar a remoção de zumbis, tentamos limpar os caches, como recomendado no LKML: sync; echo 3 > /proc/sys/vm/drop_caches, — mas o núcleo acabou sendo mais complicado e travou a máquina.

O que fazer? O problema é corrigido (o commit, e a descrição pode ser encontrada em notas de lançamento) atualizando o núcleo Linux para a versão 4.16.

História 3. Systemd e seu mount

Novamente, o kubelet consome muitos recursos em alguns nós, mas desta vez — já memória:

Descobriu-se que há um problema no systemd usado no Ubuntu 16.04, que ocorre ao gerenciar montagens criadas para conectar subPath de ConfigMaps ou segredos. Após a conclusão do trabalho do pod, o serviço systemd e seu mount auxiliar permanecem no sistema. Com o tempo, eles se acumulam em grande quantidade. Há até questões sobre isso:

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

… em que a última se refere a um PR no systemd: #7811 (questão no systemd — #7798).

O problema não existe mais no Ubuntu 18.04, mas se você quiser continuar usando o Ubuntu 16.04, nossa solução alternativa pode ser útil.

Portanto, fizemos o seguinte 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

… e nele é utilizado o seguinte 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

… e ele é executado a cada 5 minutos usando o já mencionado supercronic. Seu Dockerfile é assim:

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"]

História 4. Concorrência no agendamento de pods

Foi observado que: se temos um pod alocado em um nó e sua imagem leva muito tempo para ser baixada, outro pod que 'caiu' nesse mesmo nó simplesmente não começa a puxar a imagem do novo pod.Em vez disso, ele espera até que a imagem do pod anterior tenha sido baixada. Como resultado, o pod que já foi agendado e cuja imagem poderia ser baixada em apenas um minuto, ficará por um tempo prolongado no status containerCreating.

Nos eventos, teremos algo assim:

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

Assim, uma única imagem de um registro lento pode bloquear o deploy no nó.

Infelizmente, não há muitas soluções para isso:

1. Tente usar seu Docker Registry diretamente no cluster ou diretamente com o cluster (por exemplo, GitLab Registry, Nexus, etc.);
2. Utilize ferramentas como kraken.

História 5. Congelamento de nós devido à falta de memória

Durante a operação de várias aplicações, também encontramos situações em que um nó se torna completamente inacessível: não responde ao SSH, todos os demônios de monitoramento falham e nos logs não há nada (ou quase nada) de anômalo.

Vou mostrar através de imagens um exemplo de um nó onde o MongoDB estava funcionando.

Assim é como o atop aparece até falhas:

E assim — após falhas:

O monitoramento também mostra um salto abrupto, no qual o nó se torna inacessível:

Dessa forma, das capturas de tela, pode-se ver que:

1. A memória RAM na máquina está quase no fim;
2. Observa-se um salto brusco no consumo de memória RAM, após o qual o acesso a toda a máquina é abruptamente interrompido;
3. Um grande trabalho chega ao Mongo, que faz com que o processo do SGBD use mais memória e leia ativamente do disco.

Aparentemente, se em Linux a memória livre acabar (surge pressão de memória) e não há swap, até a chegada do OOM killer pode resultar em um equilíbrio entre o armazenamento de páginas na cache de página e a gravação delas de volta no disco. Isso é gerenciado pelo kswapd, que bravamente libera o máximo possível de páginas de memória para a distribuição subsequente.

Infelizmente, sob grande carga de I/O junto com uma quantidade pequena de memória livre, kswapd se torna o gargalo de todo o sistema, pois ele controla tudo as alocações (page faults) de páginas de memória no sistema. Isso pode continuar por muito tempo, se os processos não decidirem usar mais memória e ficarem presos à beira do abismo do OOM killer.

Surge a pergunta: por que o OOM killer chega tão tarde? Na sua iteração atual, o OOM killer é extremamente burro: ele finalizará um processo apenas quando uma tentativa de alocar uma página de memória falhar, ou seja, se o page fault ocorrer com erro. Isso demora bastante para acontecer, porque o kswapd bravamente libera páginas de memória, despejando a cache de página (todo I/O de disco no sistema, na verdade) de volta para o disco. Para mais detalhes, com uma descrição dos passos necessários para resolver tais problemas no núcleo, é possível ler aqui.

Esse comportamento deve melhorar com o núcleo Linux 4.6+.

História 6. Os pods ficam pendentes no estado Pending

Em alguns clusters, onde realmente funcionam muitos pods, começamos a notar que a maior parte deles permanece muito tempo 'pendurada' no estado Pending, embora os contêineres Docker já estejam em execução nos nós e possam ser manipulados manualmente.

No entanto, em describe não há nada de errado:

  Type    Reason                  Age                From                     Message
  ----    ------                  ----               ----                     -------
  Normal  Scheduled               1m                 default-scheduler        Atribuição bem-sucedida de sphinx-0 para ss-dev-kub07
  Normal  SuccessfulAttachVolume  1m                 attachdetach-controller  AttachVolume.Attach sucedido para o volume "pvc-6aaad34f-ad10-11e8-a44c-52540035a73b"
  Normal  SuccessfulMountVolume   1m                 kubelet, ss-dev-kub07    Volume Mount.SetUp sucedido para o volume "sphinx-config"
  Normal  SuccessfulMountVolume   1m                 kubelet, ss-dev-kub07    Volume Mount.SetUp sucedido para o volume "default-token-fzcsf"
  Normal  SuccessfulMountVolume   49s (x2 over 51s)  kubelet, ss-dev-kub07    Volume Mount.SetUp sucedido para o volume "pvc-6aaad34f-ad10-11e8-a44c-52540035a73b"
  Normal  Pulled                  43s                kubelet, ss-dev-kub07    A imagem do contêiner "registry.example.com/infra/sphinx-exporter/sphinx-indexer:v1" já está presente na máquina
  Normal  Created                 43s                kubelet, ss-dev-kub07    Contêiner criado
  Normal  Started                 43s                kubelet, ss-dev-kub07    Contêiner iniciado
  Normal  Pulled                  43s                kubelet, ss-dev-kub07    A imagem do contêiner "registry.example.com/infra/sphinx/sphinx:v1" já está presente na máquina
  Normal  Created                 42s                kubelet, ss-dev-kub07    Contêiner criado
  Normal  Started                 42s                kubelet, ss-dev-kub07    Contêiner iniciado

Depois de investigar, fizemos a suposição de que o kubelet simplesmente não consegue enviar todas as informações sobre o estado dos pods para o servidor API a tempo, incluindo os verificações de liveliness/readiness.

E ao examinar a ajuda, encontramos os seguintes parâmetros:

--kube-api-qps - QPS a usar ao se comunicar com o servidor API do Kubernetes (padrão 5)
--kube-api-burst  - Explosão a usar ao se comunicar com o servidor API do Kubernetes (padrão 10) 
--event-qps - Se > 0, limita a criação de eventos por segundo a este valor. Se 0, sem limites. (padrão 5)
--event-burst - Tamanho máximo de um registro de eventos explosivos, permite temporariamente que registros de eventos cresçam para este número, sem exceder event-qps. Usado apenas se --event-qps > 0 (padrão 10) 
--registry-qps - Se > 0, limita o QPS de puxadas do registro a este valor.
--registry-burst - Tamanho máximo de puxadas explosivas, permite temporariamente que puxadas cresçam para este número, sem exceder registry-qps. Usado apenas se --registry-qps > 0 (padrão 10)

Como pode ser visto, os valores padrão são bastante pequenos, e em 90% dos casos atendem a todas as necessidades... No entanto, no nosso caso, isso se mostrou insuficiente. Portanto, definimos os seguintes valores:

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

… e reiniciamos os kubelets, após o que nos gráficos de acesso ao servidor API, vimos a seguinte situação:

… e sim, tudo começou a funcionar!

P.S.

Agradeço muito aos inúmeros engenheiros da nossa empresa pela ajuda na coleta de bugs e na elaboração do artigo, em especial ao colega da nossa equipe de P&D, Andrei Klimentiev (zuzzas).

P.P.S.

Confira também em nosso blog:

• «O plugin kubectl-debug para depuração em pods Kubernetes».
• Dicas e truques do Kubernetes:
  • «Migração de recursos operando em cluster sob o gerenciamento do Helm 2»;
  • «Sobre a alocação de nós e as cargas em aplicações web»;
  • «Acesso a ambientes dev»;
  • «Acelerando o bootstrap de grandes bases de dados».

Fonte: habr.com