Kubernetesから出力されるログを一意的なIDで関連づけ　トラブル原因特定を容易にするロギング強化機能

サーバーの性能解析からK8sを活用したシステム構築へ

長谷仁氏（以下、長谷）：それではこのタイトルで富士通の長谷と小林から発表いたします。

本日は、最初にロギング機能の概要について説明し、そのあと現代のKubernetesにおけるロギング機能の課題について説明します。次に、その課題に対する解決策について説明をします。この解決策というのは、今のKubernetesのコミュニティ上で開発しようとしている、その開発状況について説明します。最後に、今の残課題と今後の予定について共有できればいいなと思います。

まず中身に入る前に、自己紹介ですが、今話しているのが長い谷と書いて長谷と言います。私は、もともとKubernetesの仕事ではなくて、サーバーのハードウェアとかBIOSとかOSとか、あとは仮想化層とか、そういったところの性能解析やチューニングをメインに仕事していました。

具体的には、今富士通で作っているサーバーについて、仮想系の性能ベンチマークを使って富士通がこれから出すサーバーについての性能を測って公開するという仕事をやっていまして、そこで複数の性能世界記録を取ったり、性能に関するところを突き詰める仕事をしていました。

2018年の終わりぐらいから、Kubernetesに携わることになりまして、ここ1年間ぐらいはAWSのEKSを使ったシステム構築をやっていました。2019年の末ぐらいから、OSSを開発するチームに異動しまして、そこで現在Kubernetesでロギング強化機能に取り組んでいるので、今日はそこに関する紹介をします。次、小林さんお願いします。

小林大介氏（以下、小林）：はい。小林大介といいます。ちょっとマイクの性能が悪いのでノイズが入りますが、ご了承ください。自分のローカルの活動としましては、OSSの責任者として活動しています。

2019年からKubernetesの開発に携わり、CKA取得やコミュニティへのコントリビュート、他にロギング強化機能の共同開発者として活動しています。現在は、Kubernetes本体の他にも周辺のOSSについて社内で運用するというところにも着手しようとしています。本日はよろしくお願いします。

長谷：すみません、かなりノイズがひどいので……。前半を小林さんに喋ってもらおうと思っていましたが、私のほうで喋ることにしても大丈夫ですか？　はい。じゃあすみません。私からこのあとちょっと説明します。

Kubernetesにおけるロギング機能

長谷：最初にロギング機能の概要について紹介します。まずロギングとは？　というところからなんですが、これは一般論として、システムで発生した事象を特定の形式で時系列で記録したものを指します。例えば利用者だったり運用者の操作履歴であったりとか、ソフトとしてOSとかアプリだったりとか、ハードウェアとしてサーバーとか通信機器の稼働状況であったり、それに関する通信記録とかですかね。

こういったものを時系列で記録するものをロギングといって、このロギングの重要性としまして、システムの利用状況の把握やそれを運用管理に活用したりなどという使い方、あとは障害だったり不正アクセスを検知したときのトラブルが起こったときの調査に使います。例えば、エラーログとかアクセスログ、あとはオペレーションログから何が起こったかの原因を突き止めるみたいな。

大きくこういった2つのロギングに関する利用、重要性があると考えています。本セッションでは、このロギングの2つ目のところに書いてあるトラブルシューティングという観点でKubernetesのロギング機能について説明しとうと思います。

まずKubernetesにおけるロギング機能はというと、（スライド参照）Kubernetesでは主にここの表にある4種類のログがあると考えています。

上から順番にPodログ、イベントのログ、あとはコンポーネントのログとAuditログですね。概要について簡単に説明しますと、上のPodログについてはPod上で動作しているアプリケーションの標準出力やエラー出力をログとして出していて、アプリ側に何か問題があったときのトラブルシューティングに利用することが多いです。

2番目のイベントログは、これはKubernetesのクラスタで発生した全般的なイベントにおけるログです。トラブルシューティングの観点での主な内容としては、クラスタ側に何かあったときに見ることが多いと思っています。

3つ目がコンポーネントログで、これはKubernetesコンポーネントごとの個別のログです。例えばkubeletとかkube-apiserverとか、あとはkube-schedulerとかですね。ふだんはそんなにここのログを見ることはないかもしれませんが、イベントログよりも詳細な内部動作を追う場合に必要になってきます。

最後はAuditログとして、kube-apiserverでやり取りするHTTPのリクエスト、レスポンスに関するログで、主にセキュリティと監査に使ったりします。

これら4つのログがあるんですけど、トラブルシューティングで主に扱うログはPodのログとかイベントログが多いです。この2つのログで原因を絞り込めない場合、あとでちょっとユースケースとかを紹介しますが、そういったときにコンポーネントのログを見る場合もあります。

コンポーネントログを調査するケース例

実際にここからコンポーネントのログに入っていくんですけど、（スライド参照）コンポーネントログを調査するユースケース例をここに2つ書いています。1つ目はPodにPVがアタッチされない場合で、まず前提条件としてPVの作成までは正常にできていることを確認できています。ただ実際はPodにPVがマウントされない状況です。

この場合、ストレージ側でボリュームを作っている部分まではOKなんですけど、Pod内のコンテナへマウントするところでNGになっているという可能性が考えられます。こういった場合には原因を特性するためにノード側のシスログとかマウント管理の設定というのを疑ったりすることもあると思うんですけど、実際にコンポーネント、kubeletのログというのを確認しながら問題箇所を探ったりということもあり得ると思っています。

2つ目のケースは、不審なユーザー操作とかクラスタ動作を検知した場合としまして、運用者が把握していないようなPod操作や予期していないPodのWorker間移動などを検知した場合です。そういったときに何が起きているか、その事象の全体像とか原因を把握したいと普通は考えていくと思っています。

そういったときに各コンポーネント、kube-schedulerとかkube-apiserverの動作内容だとか「大元のリクエストはなんだろう」とかを見て、調査の一環で一連の動作を抑えるために各コンポーネントの関連するログというのを集めてそれを精査することが必要なケースが出てきます。

ロギング機能の課題

今までの話がロギング機能の概要で、ここからはKubernetesにおけるロギング機能の課題について説明していきます。Kubernetesのロギング機能の課題なんですけど、コンポーネントを跨るログ調査が必要になってきたときに、そういった作業を実際にやろうと思うと、ちょっと難しいというのがあります。

Kubernetesでは任意の操作、例えばkubectl applyとかcreateとかdeleteとか、そういたコマンドをユーザーが叩いたときに、その延長で複数のコンポーネントが動作します。なので、クラスタ内部で何か操作をして何か起こったときに、一連の動作を追おうと思った場合には、コンポーネントに跨ったログ解析が必要になってきます。

ただ、Kubernetesのコンポーネントのログは、コンポーネントごとに独立して出力されるアーキテクチャになっているため、個々のコンポーネントから一連の動作を追おうと思うと、関連するログを見つけ出して、それらを関連づける作業が必要になってきます。ここの下の図にある通り、master側やwokerノード側に各Kubernetesのコンポーネントがあり、それらのログは個別に出力されます。

なぜコンポーネントごとにログが独立して出ているのかという理由なのですが、これはKubernetesのアーキテクチャに起因しています。KubernetesではクラスタのDesiredな状態という、望ましい状態ですかね。例えばデプロイメントの数とかだったりというのをEtcdとかに保存しています。

各Kubernetesのコンポーネントは、kube-apiserverと通信してEtcd内にあるDesiredな状態と、あとは現在の状態を比較して、そこに差分があった場合はDesiredな状態に保つように動いていくというアーキテクチャになっています。

なので、各コンポーネントがDesiredかどうかを見て、そのDesiredな状態にするために各自独立して動く仕組みのため、ログも独立して出力されるという、そういった構造になっているのが原因です。

実際に、こういったコンポーネントごとにログが独立している状態で、どうやって関連するログを紐づけていくかという話なんですけど、今ある手法で考えられているのは、各コンポーネントのログをリソース名でフィルタリングするというものです。わかりやすいところでいうと、Pod作成とかでいうのであれば、Pod名とかそういったリソース名で各ログを検索でかけてやれば、おおよそ関連するようなログは抽出できてくると思います。

あとは各コンポーネントのログというのはそれぞれタイムスタンプが出ているので、タイムスタンプ順に並べて、近い時間帯のログというのを精査して、何が起こったかを突き止めるというやり方も考えられると思います。

ただ、これらの手法には課題がありまして、リソース名のないログは簡単な検索だけで抽出できないですし、同じ時間帯に複数のリクエストが投げられている場合は、それをタイムスタンプで並べたとしても仕分けるのにそれぞれ時間がかかる問題もあります。

一意なIDである「Request ID」を付与し、解決する

これに対する解決策ですが、今はRequest IDという機能を開発しようとしています。任意のユーザーの操作、kubectl applyなどの結果として、各コンポーネントがそれぞれ出すログに、一意なIDである「Request ID」を付与するという機能を作ろうとしています。

これのメリットとしては、一連のKubernetes内部の動作を追う場合に、各コンポーネントのログをRequest IDでクエリ検索をかけてあげるだけで、関連するログを簡単に抽出できるメリットがあります。これによって、リソース名のないログにも対応できますし、タイムスタンプやログの内容精査とかそういった仕分ける作業も不要になります。

今Request IDを実際に使ったユースケースとして、最初のほうでコンポーネントのログを見るユースケースを2つ紹介したと思うんですけど、それぞれについて、Request IDを使うとこうなります。

まずPodへPVがアタッチされないケースで、Request IDを用いた場合、Kubernetes内のどの処理まで進み、どの処理でエラーになったかを即座に特定できます。これによって実際に問題がある箇所を、ある程度高い確率で絞り込むことができます。

結果として、実際に調査する範囲が狭まることによって、原因特定を容易化できると考えています。まとめますと、エラー検知時に元となったユーザー操作とか、どのような経緯をたどってそのエラーが出たかについて、関連するログを容易に抽出できる効果を発揮します。

2つ目のケースとして、不審なユーザー操作やクラスタ動作を検知したケースで、これもRequest IDを用いると1度のクエリ操作で関連するログをすべて抽出できます。それによって、そこから何が起きているのか、原因範囲の絞り込みや事象把握に要する時間を短縮可能になります。これをまとめますと、任意のユーザー操作に対して結果として出力される各コンポーネントのログを簡単に抽出できる効果があります。

これはRequest IDを付与したときのログイメージになります。ここでは例として、Deploymentの作成操作に関するログというのを一部抜粋しながらここに上げています。これはkube-apiserverやkube-controller-manager、kubeletがあるんですけど、それぞれのログの末尾にreqIDを付与するイメージをしています。

実際にこのRequest IDをキーにログを抽出して、そこからさらに時系列順で整理をすることによって、一連の処理の流れの把握が容易になることを狙っています。エラーログから原因を調査する場合には、エラーログにもRequest IDを付与しようと考えているので、それをキーにして検索をすることで、エラーまでの一連の流れとかが見えるようになってきます。

ここでは、この手作業で切り貼りしたものを出していますが、実際に運用で使おうと思った場合は、ログの収集とか解析とか可視化は、ElasticsearchやKibana、Fluentdなど既存のOSSがあるので、それを使うことを想定しています。

開発の現状

ここからは、今このRequest IDをコミュニティで作ろうとしているのですが、そこの状況について説明していきます。

まずは開発の現状としてコミュニティの状況ですが、（スライド参照）上に貼っているのが提案中の機能のURLでして、これはKEPというKubernetesに対する機能提案という形式に則ったかたちで提案をしています。このKEPの提案は現在Privisionalというステータスで、これは機能の設計段階を意味していて、この設計の合意が取れたら、今度は次にimplementableという実装段階に入ります。

今はその手前で、機能の設計についてコミュニティと議論している段階になります。提案中の主要な機能としてRequest IDフラグがありまして、これはログに実際にRequest IDを付与するかどうかをON/OFFするフラグを考えています。

あとはRequest IDを付与する対象としまして、今回主要なユーザー操作であるkubectl applyやdelete、createなど、よく使うユーザー操作に限定することを考えています。この理由はあとで詳細に説明します。

一方で開発予定にない機能は、使用頻度の低いユーザー操作に対するRequest IDの付与です。これはkubectlのサブコマンドごとに個別の修正が必要になってくるのが現状のため、すべてのサブコマンドに対応するには、時間や工数上の問題があるということで、今回は優先度を決めて対象を選定しています。

あとは他に開発予定にない機能としてログ収集、分析、可視化というのは既存の有用なOSSがあるので、そこで対応可能と考えています。