百日半狂乱

Shut the fuck up and write some code!!

Nodeのマシンタイプをケチって覚えたdebugging kubernetes

GKE上に立ち上げている自前のkubernetesのClusterは、一番安いという理由だけでg1-small*1を使い続けていた。しかし、いざ複数のPodを追加したりし始めると、Nodeのリソース不足が原因で色々ハマったので、そこで覚えた細かいデバッグ手法をのごとく逆引き辞書っぽくメモしていく。ついでにリソースとは無関係なkubernetesのネットワーク関連でハマったこともメモ。すでに使い込んでいる人にとって目新しいものはない気がする。

以下、例となっているPodのデプロイは、状況を再現しやすいという理由だけで手前味噌のprometheus実験レポジトリを元に行っているのでprometheusが云々と多少言っているが、基本的にPodの内容がなんであれ、リソースが足りなくなった場合に何が起こって、kubectlで何を確かめれば良さそうか、という点を中心に書き下していく。

Check kubectl describe nodes

kubectl describe nodesでNodeのリソース使用状況を見ることができる。g1-smallのNode一つだけでClusterを組んでいると、何もしていなくてもkube-system にリソースの75%を以上を食われていることがわかる。ここから自分のPodを適宜追加していくことになるので、早晩リソースが枯渇する。実に世知辛い。

$ kubectl describe nodes
......
  Namespace                  Name                                                  CPU Requests  CPU Limits  Memory Requests  Memory Limits
  ---------                  ----                                                  ------------  ----------  ---------------  -------------
  kube-system                event-exporter-v0.2.1-5f5b89fcc8-hzgtm                0 (0%)        0 (0%)      0 (0%)           0 (0%)
  kube-system                fluentd-gcp-scaler-7c5db745fc-xdfw8                   0 (0%)        0 (0%)      0 (0%)           0 (0%)
  kube-system                fluentd-gcp-v3.0.0-nw4cz                              100m (10%)    0 (0%)      200Mi (17%)      300Mi (25%)
  kube-system                heapster-v1.5.3-f767c7cdc-7q82r                       138m (14%)    138m (14%)  301456Ki (25%)   301456Ki (25%)
  kube-system                kube-dns-788979dc8f-cf94z                             260m (27%)    0 (0%)      110Mi (9%)       170Mi (14%)
  kube-system                kube-dns-autoscaler-79b4b844b9-nzdm6                  20m (2%)      0 (0%)      10Mi (0%)        0 (0%)
  kube-system                kube-proxy-gke-hands-on-default-pool-d9f87312-9r5g    100m (10%)    0 (0%)      0 (0%)           0 (0%)
  kube-system                kubernetes-dashboard-598d75cb96-j5dfd                 50m (5%)      100m (10%)  100Mi (8%)       300Mi (25%)
  kube-system                l7-default-backend-5d5b9874d5-bkz4g                   10m (1%)      10m (1%)    20Mi (1%)        20Mi (1%)
  kube-system                metrics-server-v0.2.1-7486f5bd67-bhjcx                53m (5%)      148m (15%)  154Mi (13%)      404Mi (34%)
Allocated resources:
  (Total limits may be over 100 percent, i.e., overcommitted.)
  CPU Requests  CPU Limits  Memory Requests  Memory Limits
  ------------  ----------  ---------------  -------------
  731m (77%)    396m (42%)  909712Ki (76%)   1524112Ki (128%)

CPU Requests/CPU Limits/Memory Requests/Memory Limits

例えば、Podを2つデプロイしてみる(ここではdevelopment-monitoringというnamespaceにprometheusalertmanagerのPodを一つずつ追加している)。

$ kustomize build overlays/development | kubectl apply -f -
......
deployment "development-alertmanager" created
deployment "development-prometheus" created

たった二つPodを追加しただけで、 CPU Requestsの合計が99%Memory Requests93%になっていることがわかる。Nodeはもうすでに限界である。

$ kubectl describe nodes
......
  Namespace                  Name                                                  CPU Requests  CPU Limits  Memory Requests  Memory Limits
  ---------                  ----                                                  ------------  ----------  ---------------  -------------
  development-monitoring     development-alertmanager-6b46bd5bf9-xz2f7             100m (10%)    100m (10%)  100Mi (8%)       100Mi (8%)
  development-monitoring     development-prometheus-859579ff98-2pf87               100m (10%)    100m (10%)  100Mi (8%)       150Mi (12%)
  kube-system                event-exporter-v0.2.1-5f5b89fcc8-hzgtm                0 (0%)        0 (0%)      0 (0%)           0 (0%)
  kube-system                fluentd-gcp-scaler-7c5db745fc-xdfw8                   0 (0%)        0 (0%)      0 (0%)           0 (0%)
  kube-system                fluentd-gcp-v3.0.0-nw4cz                              100m (10%)    0 (0%)      200Mi (17%)      300Mi (25%)
  kube-system                heapster-v1.5.3-f767c7cdc-7q82r                       138m (14%)    138m (14%)  301456Ki (25%)   301456Ki (25%)
  kube-system                kube-dns-788979dc8f-cf94z                             260m (27%)    0 (0%)      110Mi (9%)       170Mi (14%)
  kube-system                kube-dns-autoscaler-79b4b844b9-nzdm6                  20m (2%)      0 (0%)      10Mi (0%)        0 (0%)
  kube-system                kube-proxy-gke-hands-on-default-pool-d9f87312-9r5g    100m (10%)    0 (0%)      0 (0%)           0 (0%)
  kube-system                kubernetes-dashboard-598d75cb96-j5dfd                 50m (5%)      100m (10%)  100Mi (8%)       300Mi (25%)
  kube-system                l7-default-backend-5d5b9874d5-bkz4g                   10m (1%)      10m (1%)    20Mi (1%)        20Mi (1%)
  kube-system                metrics-server-v0.2.1-7486f5bd67-bhjcx                53m (5%)      148m (15%)  154Mi (13%)      404Mi (34%)
Allocated resources:
  (Total limits may be over 100 percent, i.e., overcommitted.)
  CPU Requests  CPU Limits  Memory Requests  Memory Limits
  ------------  ----------  ---------------  -------------
  931m (99%)    646m (68%)  1114512Ki (93%)  1780112Ki (149%)

kubectl describe nodesの出力にあるように、各PodにはCPU Requests/CPU Limits/Memory Requests/Memory Limitsの概念があり、Nodeのリソースをケチっている世界では、これらを気をつけて調整しないとあっという間にリソースが枯渇して、以下に示すような様々な問題にぶつかることになる。

Insufficient CPU/Memory

例えば、このリソースが逼迫した状態でPodを更に二つ追加してみる(staging-monitoringというnamespaceに別のprometheusalertmanagerのPodを追加しようとしている)。

$ kustomize build overlays/staging | kubectl apply -f -
......
deployment "staging-alertmanager" created
deployment "staging-prometheus" created

kubectl get podsを見てみるとSTATUSPendingのままいつまで経ってもRunningになってくれない。

$ kubectl get pods --namespace staging-monitoring
NAME                                    READY     STATUS    RESTARTS   AGE
staging-alertmanager-57d9466c59-g22n4   0/1       Pending   0          3m
staging-prometheus-79cf6db666-9bhk9     0/1       Pending   0          3m

こういう時は、kubectl describeで詳細を見る。0/1 nodes are available: 1 Insufficient cpu, 1 Insufficient memory.とあるようにCPUもMemoryも足りねーよとスケジューラに怒られていることがわかる。

$ kubectl describe po/staging-prometheus-79cf6db666-9bhk9 --namespace staging-monitoring
Events:
  Type     Reason            Age               From               Message
  ----     ------            ----              ----               -------
  Warning  FailedScheduling  59s (x8 over 2m)  default-scheduler  0/1 nodes are available: 1 Insufficient cpu, 1 Insufficient memory.

個別のPodを見なくても、kubectl get eventsを見れば、追加したPodが両方ともリソース不足で起動できないことがわかる。

$ kubectl get events --namespace staging-monitoring
LAST SEEN   FIRST SEEN   COUNT     NAME                                                     KIND                    SUBOBJECT   TYPE      REASON                  SOURCE                        MESSAGE
8s          4m           19        staging-alertmanager-57d9466c59-g22n4.154349c73c83d2db   Pod                                 Warning   FailedScheduling        default-scheduler             0/1 nodes are available: 1 Insufficient cpu, 1 Insufficient memory.
8s          4m           19        staging-prometheus-79cf6db666-9bhk9.154349c740986daf     Pod                                 Warning   FailedScheduling        default-scheduler             0/1 nodes are available: 1 Insufficient cpu, 1 Insufficient memory.

OOMKilled due to Lack of Memory Limits

一旦、作ったPodは全部消して、改めてprometheusとalertmanagerのPodをデプロイする。ただし、ここではprometheusのMemory Limits150(150Mi (12%))としていたところを...

$ kubectl describe nodes
......
  Namespace                  Name                                                  CPU Requests  CPU Limits  Memory Requests  Memory Limits
  ---------                  ----                                                  ------------  ----------  ---------------  -------------
  development-monitoring     development-alertmanager-6b46bd5bf9-xz2f7             100m (10%)    100m (10%)  100Mi (8%)       100Mi (8%)
  development-monitoring     development-prometheus-859579ff98-2pf87               100m (10%)    100m (10%)  100Mi (8%)       150Mi (12%)

デフォルト100Mi (8%)に戻してデプロイを試みる。

  Namespace                  Name                                                  CPU Requests  CPU Limits  Memory Requests  Memory Limits
  ---------                  ----                                                  ------------  ----------  ---------------  -------------
  development-monitoring     development-alertmanager-6b46bd5bf9-fv66p             100m (10%)    100m (10%)  100Mi (8%)       100Mi (8%)
  development-monitoring     development-prometheus-569c948c95-mhqv2               100m (10%)    100m (10%)  100Mi (8%)       100Mi (8%)

デプロイ直後は上手くいっているように見える。

$ kubectl get pods --namespace development-monitoring
NAME                                        READY     STATUS      RESTARTS   AGE
development-alertmanager-6b46bd5bf9-fv66p   1/1       Running     0          5m
development-prometheus-569c948c95-mhqv2     1/1       Running   0          5m

が、prometheusを触ろうとするが何故かアクセスできない。もう一度Podの状態を確かめるとSTATUSCrashLoopBackOffになって、RESTARTSが延々とカウントアップしている。

$ kubectl get pods --namespace development-monitoring
NAME                                        READY     STATUS             RESTARTS   AGE
development-alertmanager-6b46bd5bf9-fv66p   1/1       Running            0          3m
development-prometheus-569c948c95-mhqv2     0/1       CrashLoopBackOff   4          3m

この時、最初に疑ったのはアプリケーションの問題だったので、kubectl logsでログを確認してみる*2。てっきり設定ファイルミスってprometheusが落ちているのかと思ったが、そういうわけでもなさそうに見える。

$ kubectl logs po/development-prometheus-569c948c95-mhqv2 --namespace development-monitoring
......
level=info ts=2018-07-21T05:58:44.467605798Z caller=main.go:629 msg="Completed loading of configuration file" filename=/etc/prometheus/prometheus.yaml
level=info ts=2018-07-21T05:58:44.467707848Z caller=main.go:502 msg="Server is ready to receive web requests."

kubectl describe podで詳細を見てもBack-off restarting failed containerとあるだけでなんのこっちゃと思って、PodのSTATUSを観察していると、実はRunning --> OOMKilled --> CrashLoopBackOffとなっていることを発見*3

$ watch `kubectl get pods --namespace development-monitoring`
NAME                                        READY     STATUS      RESTARTS   AGE
development-alertmanager-6b46bd5bf9-fv66p   1/1       Running     0          5m
development-prometheus-569c948c95-mhqv2     0/1       OOMKilled   5          5m

kubectl describe podをよく見直すと、実は出力の中腹あたりにReason: OOMKilledとはっきり理由が示されていた。

$ kubectl describe pod development-prometheus-569c948c95-mhqv2 --namespace development-monitoring
......
    State:          Waiting
      Reason:       CrashLoopBackOff
    Last State:     Terminated
      Reason:       OOMKilled
      Exit Code:    137
      Started:      Sat, 21 Jul 2018 15:09:47 +0900
      Finished:     Sat, 21 Jul 2018 15:10:09 +0900
......
  Warning  BackOff                2m (x33 over 12m)  kubelet, gke-hands-on-default-pool-d9f87312-9r5g  Back-off restarting failed container

Ref. Configure Out Of Resource Handling - Kubernetes

Memory limit requestを150に戻して、prometheusの実際のメモリ使用量をkubectl top podで確認すると、確かに100では足りないことがわかる。

$ kubectl top pod --namespace development-monitoring
NAME                                        CPU(cores)   MEMORY(bytes)
development-alertmanager-6b46bd5bf9-bsmzg   0m           6Mi
development-prometheus-859579ff98-w29sn     9m           120Mi

ドキュメントをよく見ると、100m/100Mi等の意味とともに、Podが殺された理由を確かめる別の方法も載っていた。

$ kubectl get pod -o go-template='{{range.status.containerStatuses}}{{"Container Name: "}}{{.name}}{{"\r\nLastState: "}}{{.lastState}}{{end}}' development-prometheus-569c948c95-bzrwr --namespace development-monitoring
Container Name: prometheus
LastState: map[terminated:map[containerID:docker://388979adb46279753bb4a5a563cef22816f836beeed0f028762d3808c6327d38 exitCode:137 finishedAt:2018-07-21T06:52:16Z reason:OOMKilled startedAt:2018-07-21T06:52:00Z]]

Debug Networking

CPU/Memoryリソース不足とは関係ないけど、ネットワーク関係でハマったこともついでにメモ。

Can not create a Load Balancer with the same name on GCP

kubernetes 1.10.5で、IngressHTTP(S) load balancerをむやみに作ったり消したりを繰り返していたら、kubectl get servicesでSTATUSがずっとPending状態になる現象に出くわした。コンソール上でもDeleting load balancerとなっていて、消したはずのロードバランサを作り直そうとしているようなエラーメッセージが出ていた。

Error deleting load balancer (will retry): GCE 200 - RESOURCE_IN_USE_BY_ANOTHER_RESOURCE: The http_health_check resource 'projects//global/httpHealthChecks/k8s-a0515c281357a0b3-node' is already being used by 'projects///regions/asia-northeast1/targetPools/a35aab2b3867711e8b08d42010a92015'

これは既知の問題でロードバランサの名前を変えてデプロイするのが(2018/07/21時点での)workaroundだと思っていたら、修正が入ったっぽい。自分で試してないけど クラスタ1.10.5-gke.3にアップグレードしたら問題が解消されたと報告がある。

There is Endpoint behind Service

問題の原因はServiceで定義するselectortypoがあっただけというしょうもないものだけど、修正の過程で知ったことをついでにメモ。

kubernetesは各Serviceに内部的なAレコードmy-svc.my-namespace.svc.cluster.localを発行してくれるので、これを使ってprometheusからalertmanagerへアラートを飛ばそうと試みたが、通信がタイムアウトをしてしまってアラートを飛ばせない。

development-prometheus-7d648b4bd8-fpgcg prometheus level=error ts=2018-07-19T10:28:52.666687678Z caller=notifier.go:473 component=notifier alertmanager=http://development-alertmanager.development-monitoring.svc.cluster.local:9093/api/v1/alerts count=1 msg="Error sending alert" err="context deadline exceeded"

kubectl run -it --rm --restart=Never busybox --image=busybox shからkubernetesの内部ネットワークにアクセスして、名前解決できているか確認して見るがちゃんとローカルIPが帰ってきている。

$ kubectl run -it --rm --restart=Never busybox --image=busybox sh --namespace development-monitoring
If you don't see a command prompt, try pressing enter.
/ # nslookup development-alertmanager.development-monitoring.svc.cluster.local
Server:    10.55.240.10
Address 1: 10.55.240.10 kube-dns.kube-system.svc.cluster.local

Name:      development-alertmanager.development-monitoring.svc.cluster.local
Address 1: 10.55.253.170 development-alertmanager.development-monitoring.svc.cluster.local
/ #

Ref. Using Source IP - Kubernetes

ところでServiceは基本service.spec.selectorで対応するPodのLabelを指定する。正しく指定している場合、endpoint controllerが対応するEndpoints自動的に作成してくれる。

The Service’s selector will be evaluated continuously and the results will be POSTed to an Endpoints object also named “my-service”.

さもなければ自分でEndpointsを定義する必要がある。

Services without selectors Because this service has no selector, the corresponding Endpoints object will not be created. You can manually map the service to your own specific endpoints:

Ref. Services - Kubernetes

Services without selectors

このLabel指定にtypoがあると対応するPodが見つからないのでselectorの設定がないのと同じ扱いとなり、結果的に以下のような感じで必要なEndpointsの値が尽く見当たらない状態になってしまう。

$ kubectl get endpoints --namespace development-monitoring
NAME               ENDPOINTS   AGE
development-alertmanager   <none>      13m
development-prometheus     <none>      13m
$ kubectl describe endpoints development-alertmanager
Name:         development-alertmanager
Namespace:    development-monitoring
Labels:       app=monitoring
              name=alertmanager
              variant=development
Annotations:  <none>
Subsets:
Events:  <none>

デバッグ中はEndpointsの存在を認識せずにprometheusやServiceのドキュメントなりissueを漁っていたので、今見ると如何にも怪しいEndpoints: <none>も目に入ってこない。

$ kubectl describe service/development-alertmanager
Name:              development-alertmanager
Namespace:         development-monitoring
Labels:            app=monitoring
                   name=alertmanager
                   variant=development
......
Selector:          app=monitoring,deployment=alertmanager,variant=development
Type:              ClusterIP
IP:                10.55.246.213
Port:              <unset>  9093/TCP
TargetPort:        9093/TCP
Endpoints:         <none>
Session Affinity:  None
Events:            <none>

Services with selectors

正しく設定すると、clusterIPとは別にEndpointsのIPが現れる。

$ kubectl get endpoints --namespace development-monitoring
NAME                       ENDPOINTS          AGE
development-alertmanager   10.52.0.150:9093   59m
development-prometheus     10.52.0.151:9090   59m
$ kubectl describe endpoints development-alertmanager --namespace development-monitoring
Name:         development-alertmanager
Namespace:    development-monitoring
Labels:       app=monitoring
              name=alertmanager
              variant=development
Annotations:  <none>
Subsets:
  Addresses:          10.52.0.150
  NotReadyAddresses:  <none>
  Ports:
    Name     Port  Protocol
    ----     ----  --------
    <unset>  9093  TCP

Events:  <none>
$ kubectl describe service/development-alertmanager --namespace development-monitoring
Name:              development-alertmanager
Namespace:         development-monitoring
Labels:            app=monitoring
                   name=alertmanager
                   variant=development
......
Selector:          app=monitoring,name=alertmanager,variant=development
Type:              ClusterIP
IP:                10.55.253.170
Port:              <unset>  9093/TCP
TargetPort:        9093/TCP
Endpoints:         10.52.0.150:9093
Session Affinity:  None
Events:            <none>

知らないことは知るまで知らない。

etc...

その他、ハマる度に随時更新...

*1:値段を改めて調べて気が付いたが、preemptible VMsでGKE上にkubernetesのClusterを立ち上げることができるっぽい。しかもかなり節約になる。くっ...!!

*2:何故かsternではログが確認できない場合がある :thinking_face:

*3:デプロイ直後は頻繁にOOMKilledとなっていることを確認できるが、Podが再起動を繰り返す度に、次回の再起動までの間隔が増えているっぽいので、デバッグが長引くとずっとCrashLoopBackOffの状態のように見える