環境

Kubernetes 1.10

TL;DR

各podにはConfigure Out Of Resource Handlingを読んで適切なリソースを設定しよう

環境が突然謎の状況になる、、

AWS上でk8sを使って構成されたシステムでBad Gatewayがたまに起こる、という現象が起きました。その時に、色々とコマンドを打ってみるわけですが、いまいちよく分かりません。
kubectl get podsと打つと、

NAME                                  READY   STATUS      RESTARTS   AGE
hoge-65577497b4-2jtxl              1/1     Running     1          1h
hoge-65577497b4-2k6b6              1/1     Unknown     0          1h

Unknownって何やねん。。

kubectl describe nodeと打つと、Not Readyとか書いてます。さらに、Conditionのところを注目してみると、

Conditions:
  Type             Status    LastHeartbeatTime                 LastTransitionTime                Reason                    Message
  ----             ------    -----------------                 ------------------                ------                    -------
  OutOfDisk        Unknown   Tue, 29 Jan 2019 17:23:49 +0900   Tue, 29 Jan 2019 17:24:29 +0900   NodeStatusUnknown         Kubelet stopped posting node status.
  MemoryPressure   Unknown   Tue, 29 Jan 2019 17:23:49 +0900   Tue, 29 Jan 2019 17:24:29 +0900   NodeStatusUnknown         Kubelet stopped posting node status.
  DiskPressure     Unknown   Tue, 29 Jan 2019 17:23:49 +0900   Tue, 29 Jan 2019 17:24:29 +0900   NodeStatusUnknown         Kubelet stopped posting node status.
  PIDPressure      False     Tue, 29 Jan 2019 17:23:49 +0900   Fri, 25 Jan 2019 14:22:57 +0900   KubeletHasSufficientPID   kubelet has sufficient PID available
  Ready            Unknown   Tue, 29 Jan 2019 17:23:49 +0900   Tue, 29 Jan 2019 17:24:29 +0900   NodeStatusUnknown         Kubelet stopped posting node status.

ハードウェア関係のリソースがUnknownって何やねん。。

この状況になる前に、ちょうどメモリを食いそうな操作をしたとの情報を踏まえて、以下の仮説を立てた。
基本的にk8s側では管理下にあるnodeやpodをモニタリングしているのだが、モニタリングしてるsystem containersなどが死んでしまって、もはやどのような状態なのか分からなくなってしまっているのではないだろうか。
重要なプロセスのoom_score_adjは低い値に設定されているはずだと思っていたので、この仮説はどうなのかなー、と思いつつも各podのリソースをかなり低い値にしてみると、Bad Gatewayにならなくなった（恥ずかしながら、pod達がmaxでメモリを使うと、nodeの180%のメモリを使う設定にしていました。実際にはそんなに使わんやろってことで軽い気持ちで設定していました。。）。え、まさか本当にOOMkillerに殺されてるの？と疑問に思ったので、以下の実験をした。

実験概要

Docker for Macを使います。Docker for Macでは内部的に仮想マシンを立ち上げ、そこにLinuxを入れています。そして、そのLinux上でコンテナが動いている、という感じです。実験の概要としては、k8sを使って、リソース制限せずpodを立ち上げて、そのpodでメモリを食いまくるプログラムを実行します。そして、どのコンテナが殺されるのかを見てみます。結論としては再現はできませんでしたが、まずい状態になることは確認できました。

セットアップ

まず、Dockerfileとかを用意しなければなりません。
ディレクトリを切って、同一階層に以下のファイルを用意します。僕の場合はk8s_experimentというディレクトリの下に以下のファイルを置きました。

まずはDockerfileです。まあ、最低限な感じです。

FROM ubuntu:16.04

RUN \
  apt-get update && \
  apt-get install -y build-essential && \
  apt-get install -y sudo

COPY mem_eater.c /var/www/app/

memoryをmmapシステムコールで要求するプログラムです。一つ引数を渡して、メモリを食います。
./mem_eater 3000とかすると3GBメモリを要求します。

mem_eater.c

#include <sys/param.h>
#include <sys/mman.h>
#include <stdint.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>


int
main(int argc, char *argv[])
{
	uintmax_t size, cnt;
	volatile uintmax_t *p, *end;
	void *scratch;
	const uintmax_t page_size = getpagesize();

	if (argc != 2) {
		fprintf(stderr, "usage: %s megabytes", argv[0]);
		return 64;
	}
	size = strtoull(argv[1], NULL, 0) * 1024 * 1024;
	scratch = mmap(NULL, (size_t) size, PROT_READ | PROT_WRITE, MAP_ANON | MAP_PRIVATE, -1, 0);
	if (scratch == MAP_FAILED) {
		perror("mmap");
		return 72;
	}
	
	fprintf(stderr, "size: %ju, psz: %ju, cnt: %ju\n", size, page_size, size / page_size);
#define STEP (page_size / sizeof *p)
	for (cnt = 0, p = scratch, end = p + size / sizeof *p; p < end; p += STEP) {
		fprintf(stderr, "%c %ju\r", "|/-\\"[cnt % 4], cnt);
		*p = ++cnt;
	}
	fprintf(stderr, "* %ju, waiting for signal\n", cnt);
	pause();
}

なんか最初はk8sでdocker stack deployとか使えば、docker-compose.ymlを使えると思っていたので、docker-compose.ymlを書きました。ちなみに、それは無理そうだったので、諦めました。まあ、なんか要らなかった感あります。

docker-compose.yml

version: '3'
services:
  hoge:
    build:
      context: ./
      dockerfile: Dockerfile-hoge

こちらを参考にして、コマンドで自動生成した後、終了しないように永遠にスリープするようにしています。

hoge-deploy.tmpl.yml

apiVersion: extensions/v1beta1
kind: Deployment
metadata:
  creationTimestamp: null
  labels:
    run: hoge
  name: hoge
spec:
  replicas: 1
  selector:
    matchLabels:
      run: hoge
  strategy: {}
  template:
    metadata:
      creationTimestamp: null
      labels:
        run: hoge
    spec:
      containers:
      - image: k8s_experiment_hoge:latest
        imagePullPolicy: IfNotPresent
        name: hoge
        command: 
        - sh 
        - "-c"
        - 'while true; do sleep 1; done'
        resources: {}
status: {}

実験開始

Docker for macでpreferencesを開き、Enable Kubernetesにcheckを入れます。さらに、Show system containers(advanced)にもチェックを入れます。Docker Engineに割り当てているリソースはMemoryが2.0GiB、スワップが1.0GiBです。この状態でdocker psとか打つと、システムコンテナー達がいるのを確認できます。

そして、imageを作って行きます。
docker-compose buildと打つと、buildできます。buildが終わったら、kubectl apply -f hoge-deploy.tmpl.ymlと打つと、podが起動します。
kubectl get podsで確認すると、

NAME                    READY     STATUS    RESTARTS   AGE
hoge-5f4d897c5d-5n9th   1/1       Running   0          18s

podが立ち上がっていますね。podの中に入っていて、mem_eater.cを実行したいと思います。kubectl exec -it hoge-5f4d897c5d-5n9th bashでpodの中に入って、cd var/www/app/した後、make mem_eaterします。そうすると、次は./mem_eater 2800とかして、メモリを食いつぶしたいところですが、一旦docker psで現状を確認します。docker psと打つと、

CONTAINER ID        IMAGE                            COMMAND                  CREATED             STATUS              PORTS               NAMES
6053cc1036a6        docker/kube-compose-controller   "/compose-controller…"   6 minutes ago       Up 6 minutes                            k8s_compose_compose-74649b4db6-gcwtw_docker_1081eb2f-2b9b-11e9-a64b-025000000001_0
a621bf35cc07        docker/kube-compose-api-server   "/api-server --kubec…"   6 minutes ago       Up 6 minutes                            k8s_compose_compose-api-7574d978fc-brg2c_docker_1081ef58-2b9b-11e9-a64b-025000000001_0
b01264055e40        k8s.gcr.io/pause-amd64:3.1       "/pause"                 6 minutes ago       Up 6 minutes                            k8s_POD_compose-74649b4db6-gcwtw_docker_1081eb2f-2b9b-11e9-a64b-025000000001_0
445294cb5865        k8s.gcr.io/pause-amd64:3.1       "/pause"                 6 minutes ago       Up 6 minutes                            k8s_POD_compose-api-7574d978fc-brg2c_docker_1081ef58-2b9b-11e9-a64b-025000000001_0
504b27f54eb7        6f7f2dc7fab5                     "/sidecar --v=2 --lo…"   7 minutes ago       Up 7 minutes                            k8s_sidecar_kube-dns-86f4d74b45-tpgn4_kube-system_814f297c-2940-11e9-b717-025000000001_4
03db81abd811        c2ce1ffb51ed                     "/dnsmasq-nanny -v=2…"   7 minutes ago       Up 7 minutes                            k8s_dnsmasq_kube-dns-86f4d74b45-tpgn4_kube-system_814f297c-2940-11e9-b717-025000000001_0
41118dff6b4b        80cc5ea4b547                     "/kube-dns --domain=…"   7 minutes ago       Up 7 minutes                            k8s_kubedns_kube-dns-86f4d74b45-tpgn4_kube-system_814f297c-2940-11e9-b717-025000000001_0
1beae4238da3        928771506b7e                     "sh -c 'while true; …"   7 minutes ago       Up 7 minutes                            k8s_hoge_hoge-5f4d897c5d-2xvbn_default_23243bf1-2b97-11e9-92e5-025000000001_0
4694f4d23310        4261d315109d                     "/usr/local/bin/kube…"   7 minutes ago       Up 7 minutes                            k8s_kube-proxy_kube-proxy-25s4r_kube-system_8148ba77-2940-11e9-b717-025000000001_0
37ecf363767e        k8s.gcr.io/pause-amd64:3.1       "/pause"                 7 minutes ago       Up 7 minutes                            k8s_POD_kube-proxy-25s4r_kube-system_8148ba77-2940-11e9-b717-025000000001_0
0a794eff3df8        k8s.gcr.io/pause-amd64:3.1       "/pause"                 7 minutes ago       Up 7 minutes                            k8s_POD_hoge-5f4d897c5d-2xvbn_default_23243bf1-2b97-11e9-92e5-025000000001_0
19d0b780cc35        k8s.gcr.io/pause-amd64:3.1       "/pause"                 7 minutes ago       Up 7 minutes                            k8s_POD_kube-dns-86f4d74b45-tpgn4_kube-system_814f297c-2940-11e9-b717-025000000001_0
2792a951901d        40c8d10b2d11                     "kube-controller-man…"   7 minutes ago       Up 7 minutes                            k8s_kube-controller-manager_kube-controller-manager-docker-for-desktop_kube-system_f916ef8176771ecab68fa5ff64fb012c_0
8cde89da1d44        52920ad46f5b                     "etcd --trusted-ca-f…"   7 minutes ago       Up 7 minutes                            k8s_etcd_etcd-docker-for-desktop_kube-system_52210da23261ada7291cb2391b166a6d_0
64725f8995b2        353b8f1d102e                     "kube-scheduler --le…"   7 minutes ago       Up 7 minutes                            k8s_kube-scheduler_kube-scheduler-docker-for-desktop_kube-system_8c33750d637b5de93e891805153e7560_0
fc64ab95d60c        e03746fe22c3                     "kube-apiserver --ad…"   7 minutes ago       Up 7 minutes                            k8s_kube-apiserver_kube-apiserver-docker-for-desktop_kube-system_5f9ce26e69fd2c057781b7e0e3992f00_0
59bcf191cf47        k8s.gcr.io/pause-amd64:3.1       "/pause"                 7 minutes ago       Up 7 minutes                            k8s_POD_kube-controller-manager-docker-for-desktop_kube-system_f916ef8176771ecab68fa5ff64fb012c_0
53b2a53446d9        k8s.gcr.io/pause-amd64:3.1       "/pause"                 7 minutes ago       Up 7 minutes                            k8s_POD_kube-scheduler-docker-for-desktop_kube-system_8c33750d637b5de93e891805153e7560_0
dc8afe920578        k8s.gcr.io/pause-amd64:3.1       "/pause"                 7 minutes ago       Up 7 minutes                            k8s_POD_kube-apiserver-docker-for-desktop_kube-system_5f9ce26e69fd2c057781b7e0e3992f00_0
f254f3d7d705        k8s.gcr.io/pause-amd64:3.1       "/pause"                 7 minutes ago       Up 7 minutes                            k8s_POD_etcd-docker-for-desktop_kube-system_52210da23261ada7291cb2391b166a6d_0

となっています。次に./mem_eater 2500とか打つと、メモリが消費され始めます。mem_eater.cは現在のメモリの消費量を表示します。最初は順調に増加して行きますが、メモリを食いつぶしてしまうと、連続的には増加しなくなります。たまに増加して、停止して、増加して、、を繰り返します。これはメモリ上のプロセスをスワップ領域に送っているためだと考えられます。

さて、スワップし始めてしばらくして、kubectl get podsと打つと、

Unable to connect to the server: net/http: TLS handshake timeout

と返ってきます。docker psと打つと、

CONTAINER ID        IMAGE                            COMMAND                  CREATED              STATUS              PORTS               NAMES
2898f937d89a        6f7f2dc7fab5                     "/sidecar --v=2 --lo…"   About a minute ago   Up About a minute                       k8s_sidecar_kube-dns-86f4d74b45-tpgn4_kube-system_814f297c-2940-11e9-b717-025000000001_1
b36fb5bbe816        c2ce1ffb51ed                     "/dnsmasq-nanny -v=2…"   About a minute ago   Up About a minute                       k8s_dnsmasq_kube-dns-86f4d74b45-tpgn4_kube-system_814f297c-2940-11e9-b717-025000000001_1
89cbf9732231        80cc5ea4b547                     "/kube-dns --domain=…"   About a minute ago   Up About a minute                       k8s_kubedns_kube-dns-86f4d74b45-tpgn4_kube-system_814f297c-2940-11e9-b717-025000000001_1
8e6741f5fe0c        353b8f1d102e                     "kube-scheduler --le…"   About a minute ago   Up About a minute                       k8s_kube-scheduler_kube-scheduler-docker-for-desktop_kube-system_8c33750d637b5de93e891805153e7560_1
fc659221bb91        40c8d10b2d11                     "kube-controller-man…"   About a minute ago   Up About a minute                       k8s_kube-controller-manager_kube-controller-manager-docker-for-desktop_kube-system_f916ef8176771ecab68fa5ff64fb012c_1
89da66900d64        e03746fe22c3                     "kube-apiserver --ad…"   About a minute ago   Up About a minute                       k8s_kube-apiserver_kube-apiserver-docker-for-desktop_kube-system_5f9ce26e69fd2c057781b7e0e3992f00_1
95291f571e86        docker/kube-compose-api-server   "/api-server --kubec…"   16 minutes ago       Up 16 minutes                           k8s_compose_compose-api-7574d978fc-brg2c_docker_1081ef58-2b9b-11e9-a64b-025000000001_0
86bbbea46bd9        docker/kube-compose-controller   "/compose-controller…"   16 minutes ago       Up 16 minutes                           k8s_compose_compose-74649b4db6-gcwtw_docker_1081eb2f-2b9b-11e9-a64b-025000000001_0
51476ab5b58a        4261d315109d                     "/usr/local/bin/kube…"   16 minutes ago       Up 16 minutes                           k8s_kube-proxy_kube-proxy-25s4r_kube-system_8148ba77-2940-11e9-b717-025000000001_0
12fa64f5e852        k8s.gcr.io/pause-amd64:3.1       "/pause"                 16 minutes ago       Up 16 minutes                           k8s_POD_compose-api-7574d978fc-brg2c_docker_1081ef58-2b9b-11e9-a64b-025000000001_0
2ee4810ec700        928771506b7e                     "sh -c 'while true; …"   16 minutes ago       Up 16 minutes                           k8s_hoge_hoge-5f4d897c5d-2xvbn_default_23243bf1-2b97-11e9-92e5-025000000001_0
f7118d3cec7f        k8s.gcr.io/pause-amd64:3.1       "/pause"                 16 minutes ago       Up 16 minutes                           k8s_POD_kube-proxy-25s4r_kube-system_8148ba77-2940-11e9-b717-025000000001_0
6b0a003f0c8b        k8s.gcr.io/pause-amd64:3.1       "/pause"                 16 minutes ago       Up 16 minutes                           k8s_POD_hoge-5f4d897c5d-2xvbn_default_23243bf1-2b97-11e9-92e5-025000000001_0
53f582698056        k8s.gcr.io/pause-amd64:3.1       "/pause"                 16 minutes ago       Up 16 minutes                           k8s_POD_compose-74649b4db6-gcwtw_docker_1081eb2f-2b9b-11e9-a64b-025000000001_0
0739048f95c2        k8s.gcr.io/pause-amd64:3.1       "/pause"                 16 minutes ago       Up 16 minutes                           k8s_POD_kube-dns-86f4d74b45-tpgn4_kube-system_814f297c-2940-11e9-b717-025000000001_0
e299aba1f638        52920ad46f5b                     "etcd --trusted-ca-f…"   16 minutes ago       Up 16 minutes                           k8s_etcd_etcd-docker-for-desktop_kube-system_52210da23261ada7291cb2391b166a6d_0
3806e8a5281a        k8s.gcr.io/pause-amd64:3.1       "/pause"                 16 minutes ago       Up 16 minutes                           k8s_POD_kube-controller-manager-docker-for-desktop_kube-system_f916ef8176771ecab68fa5ff64fb012c_0
bbecabd25873        k8s.gcr.io/pause-amd64:3.1       "/pause"                 16 minutes ago       Up 16 minutes                           k8s_POD_kube-apiserver-docker-for-desktop_kube-system_5f9ce26e69fd2c057781b7e0e3992f00_0
5b00c3464761        k8s.gcr.io/pause-amd64:3.1       "/pause"                 16 minutes ago       Up 16 minutes                           k8s_POD_etcd-docker-for-desktop_kube-system_52210da23261ada7291cb2391b166a6d_0
4b09670cb5a5        k8s.gcr.io/pause-amd64:3.1       "/pause"                 16 minutes ago       Up 16 minutes                           k8s_POD_kube-scheduler-docker-for-desktop_kube-system_8c33750d637b5de93e891805153e7560_0

いくつかの重要そうなシステムコンテナーが再起動しています。一方で、hogeは起動したままです。つまり、メモリは消費されているという状態が継続していると考えられます。よって、kubectl get podsとした時に、api serverが応答する必要があるんですが、そのpodをメモリに移動させようとしている間にタイムアウトとなる、というようなシナリオが考えられます。また、OOM killerが発動するかなと思って、仮想マシンにscreen ~/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/ttyでコンソールを繋いでみましたが、特にOOM killerが発動しているようには見えませんでした。dmesgでも見れませんでした。k8sが独自の機構で再起動しているんでしょうね。

また、docker psで見れないkubeletが死んでる可能性も考慮して、それも調べてみました。screen ~/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/ttyでコンソールに繋いだ状態で、ps aux | lessとかすると、

(略)
1180 root      0:14 kubelet --kubeconfig=/etc/kubernetes/kubelet.conf --bootstrap-kubeconfig=/etc/kubernetes/bootstrap-kubelet.conf --pod-manifest-path=/etc/kubernetes/manifests --allow-privileged=true --cluster-dns=10.96.0.10 --cluster-domain=cluster.local --cgroups-p
er-qos=false --enforce-node-allocatable= --network-plugin=cni --cni-conf-dir=/etc/cni/net.d --cni-bin-dir=/opt/cni/bin --cadvisor-port=0 --kube-reserved-cgroup=podruntime --system-reserved-cgroup=systemreserved --cgroup-root=kubepods --hostname-override=docker-for-deskt
op --fail-swap-on=false

kubeletらしき奴を発見しました。こいつをmem_eaterがメモリを食っている間、pgrep kubeletで見ていたのですが、特にkillされていませんでした。

まとめ

AWS上での挙動は再現できず、でした。ただ、重要なシステムコンテナーが再起動されていたのは確認したので、AWS上でも同様の現象が起こっていたのは予想できます。