6 bug di sistema interessanti durante l'uso di Kubernetes [e le loro soluzioni]

Negli anni di utilizzo di Kubernetes in produzione, abbiamo accumulato molte storie interessanti su come bug in vari componenti di sistema portassero a conseguenze spiacevoli e/o incomprensibili, influenzando il funzionamento dei contenitori e dei pod. In questo articolo, abbiamo raccolto alcune delle più comuni o interessanti di esse. Anche se non ti capiterà mai di trovare situazioni simili, leggere di brevi detective stories di questo tipo — soprattutto 'da una fonte diretta' — è sempre interessante, non credi?..

Storia 1. Supercronic e Docker bloccato

Su uno dei cluster, abbiamo periodicamente riscontrato un Docker 'bloccato', che impediva il normale funzionamento del cluster. Nei log di Docker, era visibile quanto segue

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 questo errore, ci interessa principalmente il messaggio: pthread_create failed: No space left on device. Uno sguardo veloce documentazione ha chiarito che Docker non riesce a forkare il processo, motivo per cui si 'bloccava' periodicamente.

La situazione nel monitoraggio è la seguente:

Situazioni simili sono osservate anche su altri nodi:

Su questi stessi nodi vediamo:

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]

Si è scoperto che questo comportamento è il risultato del funzionamento del pod con supercronic (uno strumento in Go che utilizziamo per eseguire compiti cron nei pod):

 _ 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] 
|       _ [curl] 
…

Il problema è il seguente: quando un'attività viene avviata in supercronic, il processo generato da essa non può terminare correttamente, trasformandosi in zombie.

Nota: A essere precisi, i processi vengono generati dalle attività cron, ma supercronic non è un sistema init e non può "adottare" i processi generati dai suoi figli. Quando vengono ricevuti i segnali SIGHUP o SIGTERM, questi non vengono trasmessi ai processi generati, il che porta i processi figli a non terminare, rimanendo quindi in stato di zombie. Maggiori dettagli possono essere trovati, ad esempio, in questo articolo.

Ci sono un paio di modi per risolvere il problema:

1. Come soluzione temporanea, aumentare il numero di PID nella sistema in un dato momento:

          /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. Oppure fare l'avvio delle attività in supercronic non direttamente, ma utilizzando lo stesso tini, che è in grado di terminare correttamente i processi e non generare zombie.

Storia 2. "Zombie" durante l'eliminazione di cgroup

Kubelet ha iniziato a consumare un gran numero di CPU:

Questo non piacerà a nessuno, quindi ci siamo attrezzati con perf e abbiamo iniziato a indagare sul problema. I risultati dell'indagine sono stati i seguenti:

• Kubelet spende più di un terzo del tempo di processamento per estrarre dati sulla memoria da tutti i cgroup:

  

• Nella mailing list degli sviluppatori del kernel può essere trovato una discussione sul problema. In breve, il punto è che diversi file tmpfs e altre cose simili non vengono completamente eliminati dal sistema quando si elimina un cgroup — rimangono i cosiddetti memcg zombie. Prima o poi verranno rimossi dalla page cache, tuttavia ci sono molte risorse nel server e il kernel non vede il senso di perdere tempo per rimuoverli. Pertanto continuano ad accumularsi. Perché ciò accade? Questo è un server con job cron che crea continuamente nuovi job e con essi, nuovi pod. In questo modo, vengono create nuove cgroup per i contenitori che presto vengono eliminate.
• Perché cAdvisor in kubelet impiega così tanto tempo? È facile vederlo eseguendo semplicemente time cat /sys/fs/cgroup/memory/memory.stat. Se su una macchina sana l'operazione richiede 0,01 secondi, su cron02 problematica richiede 1,2 secondi. Il problema è che cAdvisor, leggendo lentamente i dati da sysfs, tenta di considerare la memoria utilizzata anche nelle cgroup zombie.
• Per forzare la rimozione degli zombie, abbiamo provato a ripulire le cache, come raccomandato in LKML: sync; echo 3 > /proc/sys/vm/drop_caches, – ma il kernel si è rivelato più complesso e ha bloccato la macchina.

Cosa fare? Il problema viene risolto (commit, e la descrizione si trova nel messaggio di rilascio) aggiornando il kernel Linux alla versione 4.16.

Storia 3. Systemd e le sue mount

Ancora una volta, kubelet consuma troppe risorse su alcuni nodi, ma questa volta – già memoria:

Si è scoperto che c'era un problema in systemd, utilizzato in Ubuntu 16.04, che si verifica durante la gestione dei mount creati per collegare subPath da ConfigMap o secret. Dopo il termine del lavoro del pod il servizio systemd e il suo mount residuale rimangono nel sistema. Con il tempo, si accumulano in grandissimo numero. Esistono anche problemi al riguardo:

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

… nell'ultimo di questi fanno riferimento a un PR in systemd: #7811 (problema in systemd – #7798).

Il problema non esiste più in Ubuntu 18.04, ma se desideri continuare a utilizzare Ubuntu 16.04, potresti trovare utile il nostro workaround a riguardo.

Quindi, abbiamo creato il seguente 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 viene utilizzato uno script del genere:

#!/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 viene eseguito ogni 5 minuti utilizzando il già menzionato supercronic. Il suo Dockerfile appare così:

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

Storia 4. Concorrenza durante la pianificazione dei pod

È stata notata una cosa: se un pod viene collocato su un nodo e la sua immagine viene scaricata molto lentamente, allora un altro pod che "capita" su quello stesso nodo non inizia a scaricare l'immagine del nuovo pod.Invece, aspetta che l'immagine del pod precedente sia completamente scaricata. Di conseguenza, un pod già programmato la cui immagine potrebbe essere scaricata in un minuto rimarrà a lungo nello stato containerCreating.

Negli eventi ci sarà qualcosa del genere:

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

Quindi, risulta che un'unica immagine da un registro lento può bloccare il deploy sul nodo.

Sfortunatamente, ci sono poche soluzioni a questo problema:

1. Cerca di utilizzare il tuo Docker Registry direttamente nel cluster o direttamente con il cluster (ad esempio, GitLab Registry, Nexus, ecc.);
2. Utilizza strumenti come kraken.

Storia 5. Il blocco dei nodi in caso di mancanza di memoria

Durante l'utilizzo di diverse applicazioni, abbiamo anche riscontrato situazioni in cui un nodo smette completamente di essere accessibile: non risponde a SSH, tutti i demoni di monitoraggio si fermano e nei log non appare nulla (o quasi nulla) di anomalo.

Racconterò con delle immagini l'esempio di un nodo dove funzionava MongoDB.

Ecco come appare atop fino a incidenti:

Ed ecco come — la data rientri nel PITR. incidenti:

Nel monitoraggio si osserva anche un brusco picco, durante il quale il nodo smette di essere accessibile:

Pertanto, dalle schermate si vede che:

1. La memoria RAM sulla macchina è quasi esaurita;
2. Si osserva un brusco incremento del consumo di memoria RAM, dopodiché l'accesso all'intera macchina viene disconnesso bruscamente;
3. A Mongo arriva un grande compito, che costringe il processo di DBMS a utilizzare più memoria e a leggere attivamente dal disco.

Si scopre che, se in Linux finisce la memoria libera (si verifica la pressure di memoria) e non c'è swap, allora fino a l'arrivo dell'oom killer può portare a un equilibrio tra il caricamento delle pagine nella cache della pagina e il loro writeback sul disco. A occuparsene è kswapd, che coraggiosamente libera il maggior numero possibile di pagine di memoria per la successiva allocazione.

Sfortunatamente, sotto un elevato carico di I/O insieme a una scarsa disponibilità di memoria libera, kswapd diventa il collo di bottiglia dell'intero sistema, perché su di lui si concentrano tutti le allocazioni (page faults) delle pagine di memoria nel sistema. Questo può durare a lungo, se i processi non vogliono più utilizzare la memoria, ma si fissano sul bordo dell'abisso OOM killer.

Sorprende la domanda: perché l'oom killer arriva così tardi? Nella sua attuale iterazione, l'oom killer è estremamente stupido: ucciderà il processo solo quando fallirà un tentativo di allocazione di una pagina di memoria, cioè se il page fault si verifica con errore. Questo non accade per lungo tempo, perché kswapd coraggiosamente libera le pagine di memoria, resettando la cache della pagina (tutto l'I/O disco nel sistema, di fatto) sul disco. Maggiori dettagli, con una descrizione dei passaggi necessari per risolvere tali problemi nel kernel, possono essere letti qui.

Questo comportamento dovrebbe migliorare con il kernel Linux 4.6+.

Storia 6. I pod rimangono in stato di Pending

In alcuni cluster, dove funzionano davvero molti pod, abbiamo cominciato a notare che la maggior parte di essi resta a lungo "appesa" in stato Pending, sebbene i container Docker siano già in esecuzione sui nodi e possano essere gestiti manualmente.

Tuttavia, in describe non c'è nulla di sbagliato:

  Type    Reason                      Age                From                     Message
  ----    ------                      ----               ----                     -------
  Normal  Scheduled                   1m                 default-scheduler        Assegnato con successo sphinx-0 a ss-dev-kub07
  Normal  SuccessfulAttachVolume      1m                 attachdetach-controller  AttachVolume.Attach riuscito per il volume "pvc-6aaad34f-ad10-11e8-a44c-52540035a73b"
  Normal  SuccessfulMountVolume       1m                 kubelet, ss-dev-kub07    MountVolume.SetUp riuscito per il volume "sphinx-config"
  Normal  SuccessfulMountVolume       1m                 kubelet, ss-dev-kub07    MountVolume.SetUp riuscito per il volume "default-token-fzcsf"
  Normal  SuccessfulMountVolume       49s (x2 su 51s)  kubelet, ss-dev-kub07    MountVolume.SetUp riuscito per il volume "pvc-6aaad34f-ad10-11e8-a44c-52540035a73b"
  Normal  Pulled                      43s                kubelet, ss-dev-kub07    Immagine del container "registry.example.com/infra/sphinx-exporter/sphinx-indexer:v1" già presente sulla macchina
  Normal  Created                     43s                kubelet, ss-dev-kub07    Container creato
  Normal  Started                     43s                kubelet, ss-dev-kub07    Container avviato
  Normal  Pulled                      43s                kubelet, ss-dev-kub07    Immagine del container "registry.example.com/infra/sphinx/sphinx:v1" già presente sulla macchina
  Normal  Created                     42s                kubelet, ss-dev-kub07    Container creato
  Normal  Started                     42s                kubelet, ss-dev-kub07    Container avviato

Esaminando la situazione, abbiamo ipotizzato che kubelet semplicemente non riesca a inviare all'API-server tutte le informazioni sullo stato dei pod, sulle probe di liveness/readiness.

Esaminando l'help, abbiamo trovato i seguenti parametri:

--kube-api-qps - QPS da utilizzare mentre si comunica con l'apiserver di kubernetes (default 5)
--kube-api-burst  - Burst da utilizzare mentre si comunica con l'apiserver di kubernetes (default 10) 
--event-qps - Se > 0, limita le creazioni di eventi al secondo a questo valore. Se 0, illimitato. (default 5)
--event-burst - Dimensione massima di un record di eventi bursty, consente temporaneamente ai record di eventi di superare questo numero, senza superare l'event-qps. Utilizzato solo se --event-qps > 0 (default 10) 
--registry-qps - Se > 0, limita il QPS di pull del registro a questo valore.
--registry-burst - Dimensione massima dei pull bursty, consente temporaneamente ai pull di superare questo numero, senza superare il registry-qps. Utilizzato solo se --registry-qps > 0 (default 10)

Come si vede, i valori di default sono piuttosto piccoli, e nel 90% dei casi coprono tutte le esigenze… Tuttavia, nel nostro caso si sono rivelati insufficienti. Pertanto abbiamo impostato i seguenti valori:

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

… e abbiamo riavviato i kubelet, dopo di che nei grafici delle richieste all'API-server abbiamo visto il seguente scenario:

… e sì, tutto ha cominciato a volare!

P.S.

Desidero esprimere una grande gratitudine ai numerosi ingegneri della nostra azienda per l'aiuto nella raccolta dei bug e nella preparazione dell'articolo, in particolare al collega del nostro team R&D, Andrey Klimentyev (zuzzas).

P.P.S.

Leggi anche nel nostro blog:

• «Plugin kubectl-debug per il debug nei pod di Kubernetes».
• Ciclo di suggerimenti e trucchi per Kubernetes:
  • «Traduzione delle risorse in cluster sotto la gestione di Helm 2»;
  • «Sulla distribuzione dei nodi e sui carichi dell'applicazione web»;
  • «Accesso alle piattaforme di sviluppo»;
  • «Acceleriamo il bootstrap di grandi basi di dati».

Fonte: habr.com