KubernetesでPod終了時の503エラーを対処する

こんにちは。この度、10月からWantedly Infrastructure Squadで3週間インターンをさせていただいている@kn5suzukiです。

EKSについての課題に取り組み、本日はインターン最終日ということで、この3週間の成果をこちらのブログにまとめさせていただこうと思います。

はじめに

自己紹介

自分は現在修士1年生で、ネットワークの研究室に所属しております。

Kubernetesを触り始めたのは今年の5月くらいからで、ローカルでminikubeやkindを使ってチュートリアルをしたり、ネット記事を見てカスタムコントローラーを書いてみたり、VMを使ってmicrok8sのクラスターを作ってみたりといったお遊びをしたことがある程度のほとんど初心者です。AWSもほとんど初心者でEKSを触るのはこれが初めてでした。

Wantedlyのインフラ(2023年10月現在)

WantedlyではAWSのEKSを用いてほぼ全てのサービスがkubernetesクラスタ上で動いています。WantedlyのクラスタではALBがリクエストを受け付け、内部ではNodePortタイプのServiceを使用してサービスが公開されています。実際にアプリケーションが動いているコンテナの入っているPodにはistio-proxyはSidecarコンテナとしてデプロイされています。

インターンで取り組んだ課題

「Podのローリングアップデート時、TerminatingになっているPodにALBからのリクエストが流れくる現象の解明と対策」

課題の背景

この問題が発見されたきっかけは、とあるアプリケーションのAPIでエラーレートが高くなっていたことでした。その原因を調査すると、ローリングアップデート時にTerminatingになっているPodのistio-proxyから503エラーが発生しており、これはistio-proxyがリクエストをフォワーディングするアプリケーション側がすでに終了しているために発生したものでした。

この問題は、僕がインターンを始めた段階ではアプリケーション側のpreStopフックを用いてリクエストが流れてこなくなるまでsleepさせ、それに合わせてterminationGracePeriodSecondsを伸ばすことで解決されていました。

課題の目的

上記の対策により、現在503の発生は抑えられているものの、TerminatingになっているPodにリクエストが流れ続けることは想定されている挙動ではないので、その原因を解明する必要がありました。また、運用面でもterminationGracePeriodSecondsはローリングアップデートにかかる時間に作用するパラメータであり、これを長めに設定していることは緊急時の対応遅れの原因になる可能性があり、好ましいものではありません。

したがって、僕の課題の目的はALBからTerminatingのPodに流れてくるリクエストの原因を突き止めてそれを停止させ、terminationGracePeriodSecondsを元の長さに戻すことでした。

結論

「istio-proxyのpreStop処理が原因の一つでした」

過去の問題発生時に設定されたistio-proxyのpreStop処理の一部に、以下のような設定がありました。

while [ $(netstat -plunt | grep tcp | grep -v envoy | wc -l | xargs) -ne 0 ]; do sleep 1; done

このwhile文が最後まで終了せず、istio-proxyがdrain状態にならないことが、新しいリクエストが流れてきてしまう原因になっていると思われたため、preStopフックを利用する代わりにIstio 1.12から追加されたEXIT_ON_ZERO_ACTIVE_CONNECTIONSという機能を有効にすることで、問題の解決になるのではないかという提案をしました。

課題解決の流れ

原因の切り分け

課題については先行する調査により、以下の2点がわかっていました。

1. 503エラーはClusterIPによるサービスアクセスでは発生せず、ALBを経由した外部のアクセスでのみ発生すること
2. 最初に問題になっていたアプリケーション以外からも同様のエラーが発生していたこと

そこで、まずは原因となっているものを絞るための実験を行いました。

アプリケーション依存性

様々なアプリケーションから503が発生していたということで、このエラーがアプリケーション依存でないことの確認から行いました。

最初に問題が発見されたアプリケーションとテスト用のアプリケーションでPod終了に関するパラメータを揃え、ローリングアップデート時にどちらのアプリケーションからも503が出ることを確認する実験を行いました。この結果どちらのアプリケーションからも503が観測され、インフラ＝EKSの問題であることがわかりました。

アクセス方法依存性

クラスタ内に検証用のPodを立て、以下の3種類の方法でリクエストを送信し、503エラーが発生するか実験しました。

1. ClusterIP（service-name.namespace-name）でのアクセス
2. NodePort（NodeIP:NodePort）でのアクセス
3. ALB（外部URL）でのアクセス

結果として、クラスタ外部からのアクセスでのみ503が発生したので、kube-proxyのiptablesなどの内部ルーティングで問題が起こっているわけではないことがわかりました。ALBとPodの間で何かしらの通信経路が確保されていると考えました。

経路依存性

ALB経由のサービスアクセスでは、そのアクセス経路は1つではありません。ALBには自動で複数のIPアドレスが付与され、URLからそのいずれかのIPアドレスに対してリクエストが送信されます。また、ALBにたどり着いたリクエストはALBに設定されているターゲットグループから（デフォルトではラウンドロビンで）1つのターゲット（今回はNodePortでサービスを受け付けているNodeのうちのどれか）が選択されてリクエストが転送されます。ALBアクセスログなどからALB前後の経路と503に関係がないか調査したところ、以下の2つのことがわかりました。

• ALBに2つのIPアドレスがついている状態で503エラーが発生するとき、そのリクエストは一方のアドレスから来たものに限られる
• 503となったリクエストが転送されたNodeに偏りはなく、転送先Nodeと503には関係がないように見える

この原因についてはあまり見当がついていないです。

Istioの影響の有無

似たような状況でPodにistio-proxyがないときは503にならないという事例を見つけたので、Podからistio-proxyを取り除いて実験を行いました。その結果、503は発生せず、istio-proxyが原因の一つとなっていることがわかりました。

Istio-proxyの調査

これまでの検証からALBとIstioに原因があることがわかったので、Istioに焦点を絞って原因の解明を行いました。

パラメータ変更

KubernetesではPodの終了時に「Pod内のコンテナの終了させてPodを終了させる処理」「Serviceからのルーティング削除」「ReplicaSetやDeployment管理下からの除外」といった処理が独立に、並列に行われます。そのため、Pod内のコンテナを終了させるまでの時間などを適切に設定しなければ、すでに終了しているコンテナにリクエストが流れエラーになったりします。このようなパラメータの詳細や設定方法は以下のサイトがわかりやすいと思います。

今回、クラスタのistioに関するパラメータはデフォルトになっていたので、こちらのサイトを参考に安全に終了できる値に設定してみました。

結果としては、それでも503エラーは止まりませんでした。パラメータを極端に変化させても503の発生率や発生時間などに変化も見られなかったので、これらのパラメータには関係ない原因でエラーとなっていると考えました。

preStopの確認

先ほど述べたように、istio-proxyに設定されているpreStopの処理の一部に以下のwhile文がありました。

while [ $(netstat -plunt | grep tcp | grep -v envoy | wc -l | xargs) -ne 0 ]; do sleep 1; done

preStop処理の開始タイミングと終了タイミングでログに目印を出力させ、whileの継続条件となっているnetstatの様子を観察しました。

• tips：「echo 'hoge' > /proc/1/fd/1」のようにコマンド実行させることで「kubectl logs」コマンドから見れるようになります

この結果、pilot-agentとの通信がistio-proxyが（PodのterminationGracePeriodSecondsが経過して）強制終了されるまで終わらないため、isito-proxyが最後までdrain状態になっていないことがわかりました。

また、istio-proxyのアクセスログを調べると、ClusterIPやNodePortでのリクエストやELB_HealthcheckerはPodがTerminatingになったタイミングですぐに止まるのに対し、ALB経由のリクエストはpreStop中にもしばらく流れてきていることがわかりました（そのうちアプリケーション側が終了した後に到着したリクエストが503となっていました）。

解決方法の検討

preStopが設定された理由

当時の状況を調べると（数年前のログがちゃんと残っているのが素晴らしい）、当時は現在とは逆にアプリケーション側のコンテナより先にistio-proxyが終了してしまうことでリクエストのタイムアウトが発生していたらしいです。それを解決するために設定されたのがpreStop処理で、当時はistio-proxyが終了しなくなったことで問題が解決されたと思われます。

解決方法

istio-proxyを適切に終了しdrain状態にすることでALBからのリクエストが流れ続けてしまうという現象を防ぐことができるかもしれないと考えました（特に確証はありませんでした）。

istio 1.12から追加されたEXIT_ON_ZERO_ACTIVE_CONNECTIONSという機能はpreStopフックを設定しなくてもdrain状態でアクティブなコネクションの数を監視し、0になるのを待ってくれます。既存のpreStopを廃止し、EXIT_ON_ZERO_ACTIVE_CONNECTIONSを有効にしたところ、ALB経由のリクエストもPodがTerminatingになったタイミングで流れてこなくなることが確認されました。

積み残し

ALBからIstioに流れてくるリクエストの原因解明

ALBとIstioの間でどのようにリクエストがフォワーディングされているのかの原因解明はできませんでした。また、istio-proxyは生き続けているのに、なぜ時間解決するのかもわかっておりません。

コネクションが正常に終了することの確認

今回の実験ではcurlでリクエストを飛ばしていたため、時間のかかる処理でコネクションが正常に終了するのかといった検証はできておりません。

パラメータ調整

今回、EXIT_ON_ZERO_ACTIVE_CONNECTIONSを有効にすることで新たなリクエストが流れてこなくなるというところまで確認しましたが、最終目標であるterminationGracePeriodSecondsを短縮するというところまでは達成できませんでした。先ほど述べたようにPodの安全な終了には複数のパラメータを調整する必要があり、どのようなアプリケーションでもエラーとならないような値を見つけるまでには至りませんでした。

感想・まとめ

ほとんどKubernetes初心者で始まったインターンですが、この3週間とても勉強になりました。3週間前の自分のメモを見返すとしょうもなさすぎて恥ずかしくなります。

今回のインターンではInfra Squadの皆様の仕事を間近で見学させていただくことができ、エンジニアさんの凄さがわかりました。この3週間、自分はシングルタスクで大した成果も出していませんが（笑）、チームのエンジニアさんはこの3週間でたくさんのタスクをこなし、運用面で技術面だけでなく資金面も考えて動いていてすごかったです。

最後に、メンターさん、Infra Squadの皆様を始め僕を暖かく迎えてくださったWantedlyの皆様に深く感謝申し上げます。