☰

ログに 200 OK と表示されているのに、Kubernetes のライブネス プローブが HTTP 503 を取得する理由を確認する方法を教えてください。

tag-icon • tag-icon kubernetes
ログに 200 OK と表示されているのに、Kubernetes のライブネス プローブが HTTP 503 を取得する理由を確認する方法を教えてください。

Apache httpdでポッドをデプロイしました（公式画像、タグ 2.4.41）、ポート 8082 で HTTP/2.0 プレーンテキストを提供しており、「正常に」動作していますが、数時間ごとに再起動が見られます ( kubectl get pod/mypod、5 日間で 60 回の再起動を示しています)。

ログには常に「SIGWINCH をキャッチし、正常にシャットダウンしました」（-p、前のポッドの場合）：

$ kubectl logs -c httpdcontainer -p pod/mypod
  [...]
  127.0.0.1 - - [15/Jan/2020:11:12:27 +0000] "GET / HTTP/2.0" 200 9578
  [Wed Jan 15 11:12:40.433582 2020] [mpm_event:notice] [pid 1:tid 139963289400448] AH00492: caught SIGWINCH, shutting down gracefully
  127.0.0.1 - - [15/Jan/2020:11:12:37 +0000] "GET / HTTP/2.0" 200 9578

SIGWINCH信号はおそらくDocker経由の停止信号から来ていると思われます（公式Dockerfileによると）、たとえば Kubernetes のライブネス プローブなどでしょうか? GET リクエストは / に構成されたライブネス プローブですが、ご覧のとおり、Apache は 200 OK を正常に返しています。

Kubernetes kubelet は Apache からの 200 OK に同意していないようで、意図的にポッドを再起動しています。

$ kubectl describe pod/mypod
[...]
Type     Reason     Age                       From                                    Message
----     ------     ----                      ----                                    -------
Warning  Unhealthy  38m (x208 over 5d)        kubelet, node01.kube.mydomain.tld  Readiness probe failed: Get http://192.168.87.178:8082/: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
Normal   Killing    38m (x60 over 4d23h)      kubelet, node01.kube.mydomain.tld  Container docs failed liveness probe, will be restarted
Warning  Unhealthy  38m (x221 over 5d)        kubelet, node01.kube.mydomain.tld  Liveness probe failed: Get http://192.168.87.178:8082/: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
Normal   Pulled     38m (x60 over 4d23h)      kubelet, node01.kube.mydomain.tld  Container image "myregistry.mydomain.tld/foo/bar/myimage@sha256:<checksum>" already present on machine
Normal   Created    38m (x61 over 5d19h)      kubelet, node01.kube.mydomain.tld  Created container docs
Normal   Started    38m (x61 over 5d19h)      kubelet, node01.kube.mydomain.tld  Started container docs
Warning  Unhealthy  13m (x1644 over 5d19h)    kubelet, node01.kube.mydomain.tld  Readiness probe failed: HTTP probe failed with statuscode: 503
Warning  Unhealthy  3m16s (x1717 over 5d19h)  kubelet, node01.kube.mydomain.tld  Liveness probe failed: HTTP probe failed with statuscode: 503

ここで何が原因なのか、私には全くわかりません。私は kubeadm と Calico CNI でデプロイされた Kubernetes 1.16.4 を使用しています。

答え1

さらに詳しく調べてみると、システム ログに記録されているように、Docker デーモンがメモリ制限を超えたためにコンテナを強制終了していたようです。

Jan 15 12:12:40 node01 kernel: [2411297.634996] httpd invoked oom-killer: gfp_mask=0x14200ca(GFP_HIGHUSER_MOVABLE), nodemask=(null), order=0, oom_score_adj=998
[...]
Jan 15 12:12:40 node01 kernel: [2411297.672084] oom_reaper: reaped process 519 (httpd), now anon-rss:0kB, file-rss:0kB, shmem-rss:68kB
  • httpd がなぜ突然メモリ制限を超えてしまうのかは疑問が残りますが、ここではその範囲外です。
  • Kubernetes がメモリ制限を超えたためにコンテナが強制終了されたことを報告しない理由 (ドキュメントに従った lastState レポート）は私にとって依然として疑問のままです。
  • コンテナは stdout/stderr に書き込まれる前に Docker デーモンによって強制終了されるため、ログには 503 応答の出力は表示されない可能性があります。
  • メモリ不足が原因である場合、ここでのイベントのシーケンスをまだ理解できません。最初に正常なシャットダウン信号を受信し、応答が kubelet によって 503 (タイムアウトではない) として記録されるためです。

たとえこれが原因だとしても、Kubernetes 管理者がそれを突き止めるのは非常に悪い UX です。

関連情報