環境
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メモリを要求します。
#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を書きました。ちなみに、それは無理そうだったので、諦めました。まあ、なんか要らなかった感あります。
version: '3'
services:
hoge:
build:
context: ./
dockerfile: Dockerfile-hoge
こちらを参考にして、コマンドで自動生成した後、終了しないように永遠にスリープするようにしています。
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上でも同様の現象が起こっていたのは予想できます。