Zenn
💉

GKEでCloud Loggingにログを取り込んでいたら気づかぬ間にログが欠損していた件

2022/06/17に公開
GCP
Kubernetes
#
log
tech

Overview

DMM.comのPF事業本部ではマイクロサービス基盤として
Google Kubernetes Engine（GKE）[1]を利用しています。
今回はこのGKEで発生したトラブルの体験談とその対応を紹介します。

GKEにはCloud LogginやCloud MonitoringのインテグレーションとしてCloud Operations for GKEという機能があります。
この機能をオンにして設定するだけで、GKEで発生した様々なログをCloud Loggingに取り込むことができます。ちなみに、機能の実体としてはほぼfluentbitと認識していただいて問題ないです。

当時、弊チームのCloud Operations for GKEの設定ではアプリケーション（ワークロード）のログもCloug Loggingに送信するような設定でした。
今回はこの機能周りでトラブルがあったので以下時系列に沿って説明してきます。

問題発覚〜対応の流れ

1.ログ欠損の問い合わせを受ける

弊チームのGKEクラスタはマイクロサービス基盤として、他チームに展開しており、マルチテナント構成でした。その都合で他チームから、クラスタ関連の問い合わせも常時受け付けています。

ある日GKEクラスタを利用するあるチームから
以下のような連絡を受けたことで問題が発覚します。（※メッセージは一部編集しています）

Google CloudのCloud Loggingに出力しているマイクロサービスの
アクセスログの数が減少したので、調査・改善をお願いしたいです。

発生している現象としてはGCLBで出力されるアクセスログと比べて
マイクロサービスから出力しているアクセスログの数が半分以下になっているというものです。

その際に補足事項としてCloud Operations for GKEのドキュメントに以下の記述があるのでそれが怪しいのでは？という情報を同時に頂きました。

GKE クラスタで Cloud Operations for GKE を使用していて、GKE クラスタから大量のログを書き込む場合、それらのログの多くが継続的に Cloud Logging に表示されないことがあります。ロギングの量が、サポートされている Cloud Operations for GKE のロギング スループットを超えている可能性があります。

Cloud Operations for GKE は現在、ノードあたり最大 100 KB/秒のロギング スループットをサポートしています。GKE クラスタのノードでこれより多くのロギング スループットが必要な場合は、独自の Fluentd をデプロイしてカスタマイズし、スループットを向上させることをおすすめします。

今回問い合わせを頂いたチームのサービスには、大量のトラフィックが流れてくるため、アプリケーションの出力するアクセスログが大量すぎることで、問題の症状が顕著に現れていたようです。

2.対応方法を検討する

一旦問い合わせを受けて弊チームで対応方法を検討しました。具体的には以下の4つです。

  1. クラスタのノード数を増やす
  2. ログボリュームを減らす
  3. fluentbit(Cloud Operations for GKEの一部)を、独自で用意したfluentbitにリプレースする
    ＝ドキュメントで推奨されている方法
  4. アプリケーションログをCloud Loggingに取り込むのを廃止する

4番に関しては、もともとDatadogにもアプリケーションログを送信しているのでCloud Loggingにアプリケーションログを流す必要はないのでは？という話です。

上記の方法検討した結果、最終的に以下の理由で1,2,4の方法は基本的に厳しいということになりました。結果として、消去法的に根本解決に近い3番の独自で用意したfluentbitにリプレースする方針を採用しました。
1,2,4を採用しなかった理由は以下です。

  1. クラスタのノード数を増やす
    -> ログ量のためにノード数を増やすことはクラスタのリソース効率を悪化させる。また、ノード数を増やしても、あくまでサポートできるログ量が線形でスケールするだけなのでスループットがものすごく伸びるわけではない。そのためノード数をかなり大きくしてもまた欠損する可能性が高かった。

  2. ログボリュームを減らす
    -> 実は過去にログ削減の依頼はすでに行っており、これ以上すでに削減できるログがなかった。

  3. fluentbit(Cloud Operations for GKEの一部)を、独自で用意したfluentbitにリプレースする

  4. アプリケーションログをCloud Loggingに取り込むのを廃止する
    -> サービスの開発チームに、BQでログを分析したり、障害対応の際に過去30日間のログを即座に分析したいなどCloud Loggingを利用するニーズがあったため不可。

3.サポートに問い合わせる

対応方針が決まり、fluentbitをカスタマイズしたものにリプレースする必要があるのはわかったのですが、手元情報だとどのようにリプレースするべきなのかが不明でした。

ドキュメントにはカスタマイズしたfluentdを導入する案内がされているのですが、カスタマイズしたfluentdを入れる方法そのものしか基本記載がなく、結局何によってスループットが改善するかが明確でないため、Google Cloud[1:1]のサポートに問い合わせました。

その結果、丁寧な手順を含めたドキュメントを頂きました。
おそらくサポートできるスループット量的に、一定以上の規模のクラスターでは
発生するような事例なのかもしれません。
この手順ではfluentdではなくこれまでと同じfluentbitをカスタマイズしていれる形式になります。

詳しい話をするともともとCloud Operations for GKEでは専用のfluentbit+fluentbit-gkeという2コンテナで構成されるdaemonsetを用意してくれています。今回対応した手法は、fluentbit自体の設定や各コンテナのresource reqeust/limitをカスタムしたものにリプレースする手順になります。

手順を要約すると以下です。3,4は最終的なパフォーマンスを確認するためのものなので
実際のリリース時ではやる必要はありません。

  1. Cloud Operations for GKEによるCloud Loggingへのログ取り込むをシステムのもののみにする
    = アプリケーションログをCloud Operations for GKEに取り込ませないようにする
  2. 自前で用意したfluentbitのマニフェストをデプロイする
  3. (ログを大量に出力させ、負荷をかける)
  4. (スループットを確認する)

詳細手順についてはこのドキュメントを見てもらうのがわかりやすいので省略します。
（公開許可は頂いております）
Enabling High Throughput Logging by deploying self managed Fluentbit

余談ですが、Cloud Operations for GKEの用意してくれている既存のfluentbitの設定を変更したほうが楽じゃないの？という意見があると思います。
結論としては一時的弄ることは可能そうですがマニフェストを見ると、マスターにあるアドオンマネージャによって管理されているので、勝手に変更が書き戻されてしまいます。
よってこの方法は採用できません。

apiVersion: apps/v1
kind: DaemonSet
metadata:
  labels:
    addonmanager.kubernetes.io/mode: Reconcile
    k8s-app: fluentbit-gke
    ...
  name: fluentbit-gke
  namespace: kube-system
...

あとはHelmで独自にfluentbitを入れればいいのでは？という話もあると思います。
それに関しても検討の余地はあると思いますが、今回はいろいろな都合でHelmでfluentbitは導入しませんでした。

その理由を少し紹介すると、Cloud Operations for GKEには各Podに2つのコンテナがあり、fluentbit-gkeというコンテナの中のバイナリがいろいろな処理をしてくれているようなのでそれを流用したかったというのが大きな理由の一つです。

4. 新たに導入したfluentbitを検証する

一旦本番環境に導入する前に、検証環境に新たにfluentbitを導入し、スループットを確認しました。

検証結果の一部を共有します。
欠損が出るレベルのログ量を出力し、どれぐらいの量のログがCloud Loggingに取り込まれたかを確認します。なお検証は以下で実施しました。

  • 6ノード固定
  • 80MB/sのログを出力
  • ログを出力するPodは各ノードで同じ数になるよう分散

実験結果としてはCloud Operation for GKEのfluentbitから独自に用意したfluentbitに変えたことで、概算1ノードあたり1.5MB/s -> 8MB/sに改善しました。

Cloud Operations for GKEのスループット
Before: Cloud Operations for GKEのスループット

カスタマイズしたfluentbitのスループット
After: カスタマイズしたfluentbitのスループット

なお、今回共有したドキュメントでも記載がありますが、Cloud Loggingへのログ送信時にmetadataが増える都合で、アプリケーションが出すログ量が1.0MB/s程度であっても大体1.5倍の1.5MB/s程度で取り込まれるようです。
そのため上記図の値は厳密なアプリケーションログのログ量そのものではないことにご注意ください。

5.リリースする

開発チームの出すアプリケーションのログ量が何ノードあればさばけるのかを試算して
独自のfluentbitを入れれば、今のノード数のままで余裕をもってログを処理できることがわかったので、本番環境にまでリリースを実施しました。

なお、新たにカスタマイズしたfluentbitでワークロードのログを収集するので、Cloud Operation for GKEのワークロードログ取り込みをオフにすることになります。


GUIコンソールでのログ取り込み設定の変更

なお、サポートから頂いたドキュメントの手順通りだと
Cloud Operations for GKEの設定変更 -> カスタマイズしたfluentbitを導入
といった流れになるので、一時的にアプリケーションのログが取り込まれなくなります。

今回のケースでは以下の都合があったので移行時のログ欠損は許容するものとして
各チームにアポをとって移行を行いました。

  1. もともとログ自体は欠損していた
  2. Cloud Loggingとは別にCloud Operations for GKEとは独立した仕組みでdatadogにログを送信していた

6. リリース後のトラブルとそれに対する対応

その後リリースにも問題があったので、それについて触れていきます。

結論としては、弊チームで運用しているクラスタへのトラフィック量（＝ワークロードの吐き出すログ量）に対して、ドキュメント通りのresource limit設定では不十分でした。
resource limitが足りなかった結果、本番環境のトラフィック量に対して新たに導入したfluentbitの特定コンテナのmemory使用量がlimitに達して、
リスタートし続ける現象が発生しました。
（この箇所のCloud Loggingのログは一部欠損しました😇）

Cloud Operations for GKEのfluentbitに比べて、新たに導入したfluentbitはCPUのキャパシティも引きあげたり、fluentbit自体のconfigを弄っているので、それがメモリのキャパシティを超えてOOMを出してしまったようです。そう考えるとCloud Operations for GKEのfluentbitはOOM等でリスタートするところを見た記憶がないので、そういったところも考慮されて大きいスループットを出せるような作りになっていないのでしょうか…？あとはクラスタの規模やマシンタイプによっては、大きいスループットを出す必要はないので、Cloud Operations for GKEが無駄にリソースを確保しないように考慮されているのかもしれません。
あとはリソースの種類としてはDaemonsetなので各ノードのリソースを圧迫しないという意味も含まれていそうです。

スループットの文脈でのテストしかしていなかったので、厳密に本番相当のトラフィックを再現したログの出力形式ではなかった＋短時間での検証だった、という負荷試験のシナリオの甘さがあったと思います。また厳密な負荷試験ができなかったにせよ、何があるか分からないので、CPUやメモリを高めに設定しておいたほうがよかったですね。
上記の問題発覚後は、一時的に一旦大きくlimit値を引き揚げて数週間様子を見てから、値を引き下げて調整しました。

最終的にはポストモーテムを書いて、他チームに今回の問題を共有しつつ
他のDaemonset等のmemory limitに問題ないか確認・調整を実施して各daemonsetのメモリ使用量を監視するためのモニターを作成して対応しました。

反省

Cloud Operations for GKEがマネージドな機能ということもあって、Cloud Operations for GKEに対しての監視設定やエラーログの確認が手薄になっていた点があったとおもいます。
ただ開発チームからの問い合わせを受けられたことと、Datadogにもログを送信していた（こっちは欠損してない）ので、大きな問題にならなかったことは不幸中の幸いでした。

今回は大量のトラフィックを受け付けるサービスと、GCLBのログとの差分によって欠損にきづくことができました。クラスタ運用側としては、他チームのサービスの特性なども把握しつつ、この問題に自ら気づいて分析をするのは難しかったです。

一旦はエラーログを確認し続けるかしか方法がなかったと思います。
ただ、クラスタから出力されているログでも、ログレベルがエラーのログが大量にありました。
（なおかつログレベルはエラーだが、特に問題ないみたいなログが多かったです。）
それに埋もれて気づけなかったという点と、マネージドな機能が基本的に勝手にやってくれるという油断があったと思います。

本来はログの欠損を検知する仕組みを用意する、異常に気づくためにエラーログを監視する、もしくは公式ドキュメントにどれぐらいのスループットが保証できるか明記されているのでログの流量を見ておくべきだったと思います。

対応として、今回はカスタマイズしたfluentbitを入れたのですが、正直運用対象が増えてしまったのは好ましくおもっていません。
経験としてはクラウドプロバイダの製品を利用する規模が大きくなってくると特に、マネージドな機能に乗っかっているだけでは駄目で、その製品の機能・仕様を正確に理解し、監視する必要があり、
かつ手を加える必要があるというケースを経験できて、良い学びになったと思います。

リリース完了まで協力いただいたチームメイトと、問い合わせをしてくれたチーム、そしてGoogle Cloudのサポートの方々に深く感謝致します。

脚注

  1. Google Cloud、GKE は Google LLC の商標です。 ↩︎ ↩︎

Discussion