TL;DR

LivenessProbeの失敗によってコンテナがどのような挙動をするかをまとめました
LivenessProbeによってコンテナの再起動が発生する場合 SIGTERM が送られ、GracePeriod を待ってからコンテナが再起動する
CrashLoopBackOffはコンテナの起動時間がbackoffの遅延時間より少ない場合にCrashLoopBackOffとなり遅延が発生する
- backoffの遅延時間は10s * 2 ^ 再起動回数で計算されるが、再起動回数は起動時間が10分を超えるとリセットされる

はじめに

以下のような困った事例が発生しましたが、その時即答できなかったため調査することにしました。

発生した事象

ユーザからのリクエストを受ける一般的なWebアプリケーションのようなものを動作させている環境でたまにコンテナがダウンする現象が発生した
アプリケーションのなんらかの問題によって特定条件下(全体の数%)でアプリケーションは動作しなくなるがプロセスは生き残るコンテナがある状態
- この状態になるとLivenessProbeが失敗するためLivenessProbeの失敗によってコンテナがダウンし、再起動が発生する
- リクエストはService経由で受け付けていなくReadinessProbeによる制御はできない
再起動すると正常に稼働するようになる
本番稼働中で上記の障害をすぐ修正することは難しく、またアプリケーションを止めることもできないため上記の状態で動かし続けることになった
そのためこの状況下でもサービス全体ではダウンせず、可能な限りユーザにもエラーがでないようにすることが求められた

通常はアプリケーションを修正してくださいで済む問題ですが、上記のような状況なのでLivenessProbeが失敗するという特殊な状況下で問題なく運用できるようにどのようにコンテナが終了し、起動しなくなる時間はどのくらいかといったことを把握してそれが発生しても問題ないように上流のリクエストを処理することが求められました。

ただkubeletの正確な挙動を把握してなく、その場では良い回答ができなかったため今後のために調査することにしました。

LivenessProbe

LivenessProbeについては公式ドキュメントに以下のように記載されています。

kubeletは、Liveness Probeを使用して、コンテナをいつ再起動するかを認識します。例えば、アプリケーション自体は起動しているが、処理を継続することができないデッドロック状態を検知することができます。このような状態のコンテナを再起動することで、バグがある場合でもアプリケーションの可用性を高めることができます。

ref: https://kubernetes.io/ja/docs/tasks/configure-pod-container/configure-liveness-readiness-startup-probes/

Probeの動きはliveness,readiness,startupのどれも同じで公式ドキュメントにも書いてあります。

initialDelaySeconds: コンテナが起動してから、Liveness ProbeまたはReadiness Probeが開始されるまでの秒数。デフォルトは0秒。最小値は0。
periodSeconds: Probeが実行される頻度(秒数)。デフォルトは10秒。最小値は1。
timeoutSeconds: Probeがタイムアウトになるまでの秒数。デフォルトは1秒。最小値は1。
successThreshold: 一度Probeが失敗した後、次のProbeが成功したとみなされるための最小連続成功数。デフォルトは1。Liveness Probeには1を設定する必要があります。最小値は1。
failureThreshold: Probeが失敗した場合、KubernetesはfailureThresholdに設定した回数までProbeを試行します。 Liveness Probeにおいて、試行回数に到達することはコンテナを再起動することを意味します。 Readiness Probeの場合は、Podが準備できていない状態として通知されます。デフォルトは3。最小値は1。

ref: https://kubernetes.io/ja/docs/tasks/configure-pod-container/configure-liveness-readiness-startup-probes/#configure-probes

そのためこの設定値を参考にすればどの程度の時間、LivenessProbeによってアプリケーションの停止が発生するかは把握できます。

ここまではドキュメントにも書いてあるので把握していましたが、問題はCrashLoopBackOffの挙動になります。
Podはrestartを繰り返すとCrashLoopBackOffというステータスになります。これは開発時などによく発生するので事を見たことがある方も多いと思います。

CrashLoopBackOff

Podの再起動については公式ドキュメントこのように書いてあります。

The restartPolicy applies to all containers in the Pod. restartPolicy only refers to restarts of the containers by the kubelet on the same node. After containers in a Pod exit, the kubelet restarts them with an exponential back-off delay (10s, 20s, 40s, …), that is capped at five minutes. Once a container has executed for 10 minutes without any problems, the kubelet resets the restart backoff timer for that container.

ref: https://kubernetes.io/docs/concepts/workloads/pods/pod-lifecycle/#restart-policy

またこの記事によると以下のようも書かれています。

backoff遅延は2倍づつ増えていく
backoff遅延の初期値は10秒
backoff遅延の最大値は300秒 (5分)

となっています。これについてはv1.19.3でも変わっていないことが確認できました。

リトライの初期値: backOffPeriod = time.Second * 10
- https://github.com/kubernetes/kubernetes/blob/v1.19.3/pkg/kubelet/kubelet.go#L164
- 変数名はperiodだが、初期値にも利用している。
最大値: MaxContainerBackOff = 300 * time.Second
- https://github.com/kubernetes/kubernetes/blob/v1.19.3/pkg/kubelet/kubelet.go#L135

ただrestartを繰り返していてもCrashLoopBackOffにならなかったことを経験していたこともあり、どういう条件でCrashLoopBackOffになったりならなかったりするんでしょうか？

実験

LivenessProbe が必ず失敗するコンテナを立てた場合にどのような挙動をするか実験しました。
このときどのようなシグナルを投げるかといったGracefulShutdown周りも気になったので、シグナルを受けたら標準出力にログを出す簡単なアプリケーションを用意して実験しました。

用意したアプリケーションは以下のソースです。

package main

import (
    "fmt"
    "os"
    "os/signal"
    "syscall"
    "time"
)

func main() {
    sigChan := make(chan os.Signal, 1)
    signal.Notify(sigChan, syscall.SIGTERM)
    <-sigChan

    fmt.Print("Received SIGTERM, commencing shutting down sequence")
    time.Sleep(30 * time.Second)
}

これを必ず失敗する livenessProbe を設定した Pod でデプロイします。

apiVersion: apps/v1
kind: Deployment
metadata:
  labels:
    app: sigterm-test
  name: sigterm-test
spec:
  replicas: 1
  selector:
    matchLabels:
      app: sigterm-test
  template:
    metadata:
      labels:
        app: sigterm-test
    spec:
      containers:
      - image: sigterm-test
        name: sigterm-test
        livenessProbe:
          httpGet:
            path: /healthz
            port: 8080
          initialDelaySeconds: 3
          periodSeconds: 3

デプロイすると起動し、3 秒後に livenessProbe が動作し始め, 3 秒間隔で Probing を実施し、3回失敗すると Pod を Kill して Restart されるようになるはずなため確認しました。

以下が kubelet のログになります。

 I1120 00:24:09.812539    6358 kubelet.go:1865] SyncLoop (PLEG): "sigterm-test-6b9689899d-vwnmh_default(e3a9a9df-c3a1-4dbd-b0f8-164dd38d026d)", event: &pleg.PodLifecycleEvent{ID:"e3a9a9df-c3a1-4dbd-b0f8-164dd38d026d", Type:"ContainerStarted", Data:"e547d31ebbc9cc42c9ef6e95724d0f49277fbe7e3d1d09bd3da8bb5e85bc2f13"}
 I1120 00:24:14.626259    6358 prober.go:117] Liveness probe for "sigterm-test-6b9689899d-vwnmh_default(e3a9a9df-c3a1-4dbd-b0f8-164dd38d026d):sigterm-test" failed (failure): Get "http://10.26.7.45:8080/healthz": dial tcp 10.26.7.45:8080: connect: connection refused
 I1120 00:24:17.626056    6358 prober.go:117] Liveness probe for "sigterm-test-6b9689899d-vwnmh_default(e3a9a9df-c3a1-4dbd-b0f8-164dd38d026d):sigterm-test" failed (failure): Get "http://10.26.7.45:8080/healthz": dial tcp 10.26.7.45:8080: connect: connection refused
 I1120 00:24:20.626160    6358 prober.go:117] Liveness probe for "sigterm-test-6b9689899d-vwnmh_default(e3a9a9df-c3a1-4dbd-b0f8-164dd38d026d):sigterm-test" failed (failure): Get "http://10.26.7.45:8080/healthz": dial tcp 10.26.7.45:8080: connect: connection refused
 I1120 00:24:20.626908    6358 kubelet.go:1898] SyncLoop (container unhealthy): "sigterm-test-6b9689899d-vwnmh_default(e3a9a9df-c3a1-4dbd-b0f8-164dd38d026d)"
 I1120 00:24:20.627680    6358 kuberuntime_manager.go:631] Container "sigterm-test" ({"docker" "e547d31ebbc9cc42c9ef6e95724d0f49277fbe7e3d1d09bd3da8bb5e85bc2f13"}) of pod sigterm-test-6b9689899d-vwnmh_default(e3a9a9df-c3a1-4dbd-b0f8-164dd38d026d): Container sigterm-test failed liveness probe, will be restarted

kubectl logs でアプリケーションログを確認しても Received SIGTERM, commencing shutting down sequence が出ており、SIGTERM を受けて Pod に指定した GracePeriod の時間を待ってから終了するようになっていました。

ただ CrashLoopBackOff については記事にあったコンテナが起動時に異常終了した(終了コードが 0 以外)場合とは異なる挙動になることが確認できました。

$ kubectl get pod -w
NAME                            READY   STATUS             RESTARTS   AGE
sigterm-test-6b9689899d-d8jnl   1/1     Running   1          58s
sigterm-test-6b9689899d-d8jnl   1/1     Running   2          84s
sigterm-test-6b9689899d-d8jnl   1/1     Running   3          2m7s
sigterm-test-6b9689899d-d8jnl   1/1     Running   4          2m48s
sigterm-test-6b9689899d-d8jnl   1/1     Running   5          3m30s
sigterm-test-6b9689899d-d8jnl   0/1     CrashLoopBackOff   5          4m12s
sigterm-test-6b9689899d-d8jnl   1/1     Running            6          5m36s
sigterm-test-6b9689899d-d8jnl   0/1     CrashLoopBackOff   6          6m18s
sigterm-test-6b9689899d-d8jnl   1/1     Running            7          9m6s
sigterm-test-6b9689899d-d8jnl   0/1     CrashLoopBackOff   7          9m45s
sigterm-test-6b9689899d-d8jnl   1/1     Running            8          14m
sigterm-test-6b9689899d-d8jnl   1/1     Running            9          15m
sigterm-test-6b9689899d-d8jnl   0/1     CrashLoopBackOff   9          16m
sigterm-test-6b9689899d-d8jnl   1/1     Running            10         21m
sigterm-test-6b9689899d-d8jnl   1/1     Running            11         22m
sigterm-test-6b9689899d-d8jnl   0/1     CrashLoopBackOff   11         22m
sigterm-test-6b9689899d-d8jnl   1/1     Running            12         27m
sigterm-test-6b9689899d-d8jnl   1/1     Running            13         28m
sigterm-test-6b9689899d-d8jnl   0/1     CrashLoopBackOff   13         29m

実験では以下の結果が得られました。

LivenessProveの失敗によってコンテナが停止される場合はSIGTERMが送られて、GracePeriodの時間待つ
5回restartしたあとにCrashLoopBackOffになる
CrashLoopBackOffの待ち時間は最初は1m20s程度, 2回目は4mから5m、その後は 5m
CrashLoopBackOffのあとのrestartはCrashLoopBackOffにならない場合もあった
- 3回ほど連続して CrashLoopBackOff になったあとは交互にCrashLoopBackOffになっている

調査

なぜこのような結果になったのでしょうか？その理由をソースコードを見ながら確認していきます。

backoffにするかどうかの判定はdoBackoffで行われています。
https://github.com/kubernetes/kubernetes/blob/v1.19.3/pkg/kubelet/kuberuntime/kuberuntime_manager.go#L843
ここでIsInBackOffSinceが呼ばれて、現在がBackoffの期間内かどうかを判定しています。
IsInBackOffSinceにはhttps://github.com/kubernetes/kubernetes/blob/v1.19.3/pkg/kubelet/kuberuntime/kuberuntime_manager.go#L858 にある通りコンテナの最後の終了時間を eventTime として渡し、https://github.com/kubernetes/kubernetes/blob/v1.19.3/staging/src/k8s.io/client-go/util/flowcontrol/backoff.go#L102 で p.Clock.Now().Sub(eventTime) < entry.backoff によって判定されています。

このeventTimeはPLEG(Pod Lifecycle Event Generator)によって別のgoroutineで更新しているためLivenessProbeでコンテナを再起動する場合などは前回の起動の時間になりうることがありそうです。(コンテナのプロセスが終了した場合はPLEGでイベントが発火されて再起動するのでこの問題は発生しないと思われます。)たまに計算が合わない事象が発生するのはこれが原因のような気がしますがここは未確認なため詳しい方がいたらコメントもらえると助かります。

entry.backoff は https://github.com/kubernetes/kubernetes/blob/v1.19.3/pkg/kubelet/kuberuntime/kuberuntime_manager.go#L870 で 2 ^ Next メソッドが呼ばれた回数になっていてになっているので、2 ^ 再起動回数となります。

つまり最後の終了時間からの経過時間が10 * 2 ^ 再起動回数より少ない場合は backoff 遅延としてその間待つという実装になっています。そのため、例えば上記のようなケースの場合コンテナの稼働時間が42s程度あるため、経過時間 > backoffの遅延時間となり、5回程度再起動するまではCrashLoopBackOffにならなかったということになり、逆に起動できないようなコンテナの場合はコンテナの稼働時間がまったくないためCrashLoopBackOffとなり、単純にbackoffの遅延時間分待つことが発生するということのようです。

あとは再起動回数がリセットされる条件です。これはソースコードから洗い出しましたが、kuberuntimeではResetは呼ばれることがないようなので、GCかhasExpiredで有効期限が切れたときしかリセットされることはないようです。
他の条件もあるかと思って色々探りましたが、自分の探した限りでは見当たりませんでした。
そのため、Nextが呼ばれずにMaxContainerBackOff*2(10m)過ぎた場合にリセットされることになります。
要はNextはコンテナの起動時にしか呼ばれていないため、起動してから再起動せずに10分以上経過するとリセットされるということです。

まとめ

LivenessProbeによってコンテナの再起動が発生する場合 SIGTERM が送られ、GracePeriod を待ってからコンテナが削除される
CrashLoopBackOffはコンテナの起動時間がbackoffの遅延時間より少ない場合にCrashLoopBackOffとなり遅延が発生する
- backoffの遅延時間は10s * 2 ^ 再起動回数で計算されるが、再起動回数は起動時間が10分を超えるとリセットされる

かなり遠回りして調べてしまいましたが、kubeletの実装はあまり追ったことがなかったので勉強になりました。
kubeletは様々なmanagerなどのgoroutineが動いており、channelを使ってそれらの連携をしているためgolangの勉強にもよさそうに思いました。ついでにkubeletの実装をまとめようかとおもいましたが、PLEGだけでも参考文献のような記事になってしまうのでちょっとまとめるのは難しそうです😅

参考文献

PLEG: https://developers.redhat.com/blog/2019/11/13/pod-lifecycle-event-generator-understanding-the-pleg-is-not-healthy-issue-in-kubernetes/

今さら聞けないLivenessProbeとCrashLoopBackOffの挙動