サイレントで発生した障害の検知から改善までを振り返る

これは株式会社TimeTree Advent Calendar 2024の7日目の記事です。

はじめに

私はTimeTree SREチームのメンバーとして、弊社サービスの信頼性向上のために日々活動を行っています。

さて、サービスを運用していくうえで信頼性を担保するにはメトリクス監視やアラート、SLOを設定することが重要と言われています。TimeTreeのSREとして働いている中で、私自身が留意している点でもあります。

そうした日々の業務の中、アラートやエラーが検知できていない状態でレスポンスタイムの平均値のみが悪化し始める事象が発生しました。その事象に対するアプローチおよび対応策を記載します。

TL;DR

振り返ったら長すぎたのでまとめます。

• Fluentdコンテナをサイドカーとしてデプロイしていたが、バージョンアップ後に挙動が変わり正常に動作しない
• RailsアプリケーションがFluendにログを送ろうとしても送れずタイムアウトする
  • ログを送るまでにタイムラグがあるため、その間は正常にリクエストを処理しているように見える
• Fluentdへのログが流れずRailsアプリケーションが待ち続けた結果ヘルスチェックリクエストにもレスポンスを返さずにTimeoutしコンテナがDrainされ、再度デプロイされる
• Fluentdのバージョンアップをロールバックし事象改善
• ログ・メトリクス監視やアラートを見直すことで将来的な問題に備えることができた

前提

弊社TimeTreeのアプリケーションは簡単に記載すると以下のような構成で動作しています。

• プログラミング言語 / フレームワーク
  • Ruby on Rails
• インフラ(AWS)
  • ECS on Fargate
    • Rails / nginx / Fluentdコンテナを1つのタスクとしてデプロイ
    • 弊社ではフロントエンド系、バックエンド系などサービスごとに役割を分けてデプロイしています。
  • データストア
    • Aurora / DynamoDB / ElastiCache for Redis
• 監視ツール
  • NewRelic(主にインフラ系監視)
  • Sentry(主にアプリケーションのログ監視)

発端

TimeTreeのSREチームはEmbedd SREのような動き方をしており、各事業部に対し数名のSREが属します。
私が所属する事業部組み込みのSREチームでは、定期的に集まりAWSやNewRelicのAWS連携やAPMなどによって集約されたメトリクスを定点観測しています。

そんな中で、以下のようなメトリクスの変遷が確認できました。

このグラフは、APMによって集計された「1トランザクションあたりの処理時間(レスポンスタイム)」となり、99パーセンタイル、95パーセンタイル、中央値、平均値がそれぞれ折れ線グラフで表示されています。
また、縦に入っている灰色の点線はそのタイミングでリリースがあったことを示しています。

このうち、レスポンスタイムの 平均値 だけがとあるリリースのタイミングから遅くなっていることが分かるものの、エラーやアラートが発生している状態ではありません。
しかしながら、アラート等が無いからといってレスポンスタイムの悪化は見逃せるものではないため、調査を開始しました。

調査プロセス

初日の動き

最初の仮説

まず、初期段階の仮説としては当たり前ですが「何かしらのリリースが影響し、特定リクエストのレスポンスのうちいくつかが遅くなった結果、平均値に影響を与えたのでは？」と考えました。
そのため、直前のリリースによりレスポンスタイムが悪化した可能性が高いと判断し、開発チームに影響がありそうなリリースが無いかを確認してもらいました。
特にリリースの中にはRenovateによるアップデートの中に fog-aws が含まれており、これら外部リソースを扱うgemでレスポンスタイムが悪化した経験があるため、被疑箇所としてあり得ると考えていました。

リリースの中身を確認してもらっている最中は、並行して以下の点を確認していました。

1. 実際にユーザー影響が出ているかどうかの確認
   • カスタマーサポートへの問い合わせは無し
   • 数人で本番リソースに対してアクセスしてみても大きな影響は無い、ように見える
2. 他に影響が発生していそうか、どこかに影響が出ていないか
   • バックエンド用で使っているFargateコンテナでだけ発生していそうだった
3. 遅くなったトランザクションの傾向にはどういったものがあるか
   • 速報として開発チームに共有した時には特定のコントローラのように見えていたが、追加で確認すると複数のコントローラで遅くなっていることがわかる
   • レスポンスが遅くなったのではなくタイムアウトしている
   • 全てのレスポンスがタイムアウトしていないため、折れ線グラフの99パーセンタイル、95パーセンタイル、中央値には影響を与えず、平均値のみに影響が発生した。
   • 感覚的には中央値も影響を受けそうだとは思いましたが・・・
4. レスポンスタイム以外に悪化している要因は無いか
   • CloudWatchでメトリクスを確認していたところ、ALBのターゲット5XX系のエラー件数も増加していた

ここまで調査した時点で、全体に影響を及ぼすような変更点は無いため、Renovateによってアップデートされたパッケージのうち、被疑箇所として可能性が高いものをロールバックすることは決まっていましたが、以下のような疑問点が湧いてきました。

• gemのアップデートによってレスポンスタイムが悪化するにしても複数コントローラに影響を及ぼすことは考えにくいのでは？
  • 特に fog-aws が原因であるならば、AWSリソースへの通信時に遅くなることはあってもAWSリソースに依存しないコントローラに影響は及ぼさないのでは？
• タイムアウトするとしたら内部通信は考えにくい。しかし、AWSなどの外部サービスとの接続に失敗した場合はリトライ処理やSentryによるエラー通知が発生するのでは？

一旦この時点の方針としては、通常のリリースを行ったあとに全体に影響を及ぼすライブラリアップデートのロールバックを行おうとしていました。

しかし、通常リリースを行った後に何故か遅かったレスポンスタイムが正常に戻ってしまい、対応にあたっていたメンバーは「なんで？？？」の気持ちでいっぱいでした。

次の仮説

レスポンスタイムが正常に戻りはしましたが、腑に落ちないため更に調査を行います。
すると、以下の点がわかりました。

• Fargateで実行しているバックエンド系タスクのうち、いくつかが「port 80 is unhealthy... due to( reason Request timed out ) でDrainされていること
• 事象発生直後のリリース時、即座にレスポンスタイムの悪化 / 上記 Drainに関するログが発生していないこと
  • リリース後、およそ1時間ほどすると事象が発生しているように見え始める
  • 以下の仮説を考えている最中に事象が再発したため、今回の事象は時間起因で発生することがほぼ確定
    ( この記事を執筆している最中に思い返すと、これらのログを初動で見落としていたのは・・・ととても反省しています。 )

上記から、まずは「正常に動作していないFargateタスクがいるのでは？」と思い、以下のような仮説を考えました。

1. 正常でないFargateホストで稼働している可能性( ただし可能性としては低い )
2. 自前実装のヘルスチェック用の不具合

• こちらについては社歴の長いエンジニアと会話して教えてもらいましたが、自前実装のヘルスチェックの動作が元々重いこと、全台がヘルスチェックを実施していないことから、可能性としては高そうと感じた

この時点ですでに夕方であり、レスポンスタイムが悪化する事象は再発しているものの以下のような理由から翌日に対応する方針としました。

• バックエンド系のFargateタスクに限ってみればレスポンスタイムは悪化しているが、ネイティブアプリなども含めたサービス全体で見ればそこまで悪化していないこと
  • 影響を受けているユーザーさんもいたはずですが、普通に使えているユーザーさんの割合が多いと考えました
• 再発するまでに時間がかかるため、アップデートしたパッケージを1つずつロールバックすると長時間ほかのリリースができなくなるため
  • 影響範囲がわからなくなるため、可能ならば通常のリリースと障害対応のリリースは分けたい
  • 説明は割愛しますが、弊社のサービスが持つ特性による制約で、高頻度にデプロイしにくいため、細かいRevertのリリースを行いにくいという背景があります

2日目の動き

2日目の方針は、基本的に初日で可能性が高そうと感じたアップデートを1つずつロールバックしていき、その裏で初日の仮説として出た「自前実装ヘルスチェックの不具合」について確認しようとしていました。

ただ、別のSREメンバーと話していた際に、もう1度ちゃんとメトリクスとログを全部見直そうとなり、CloudWatchやNewRelic上で見ることのできるメトリクスをポチポチと眺め始めました。

ここで最初に気づいたのが、FargateタスクのCPU使用率が異常であることです。
異常と言ってもかなり直感的なものですが、CPU使用率のmin値が長期間 0% であることはなにかが変だと感じました。

TimeTreeはグローバル展開しており、どの時間帯でもリクエストが発生するため、CPU使用率が0%である瞬間はあってもそれは長時間続かないことがほとんどである、というのが定点観測をすることで肌感覚としてわかっています。

定期的にFargateタスクごとのCPU使用率の推移を見ていたこともあり、上記の画像にはとても違和感を覚えました。
また、CPU使用率が0%であるにもかかわらず、リクエストが処理できていないということはCPUがWait状態なのではないか？と仮説を立てました。

実際にFargateタスクの中にログインして状況は確認できず、また、NewRelic上では全タスクのCPU使用率がまとめられてしまっています。
そのため、次はCloudWatchのContainer InsightsでCPU使用率を確認します。
ここで、FluentdコンテナのCPU使用率が爆発していることに気づきました。

FluentdのCPU使用率が爆発するとしたら以下の二点が可能性としてあるな、と考えました。

1. 送られてくるログ量とCPUリソースがアンマッチ
2. 正常に起動できずに延々と起動処理を繰り返す

• こちらは、私が過去にFluentdの設定ファイルの記述を間違えて同様の事象を起こしたことがあるためです

最初は1.を考えましたが、事象発生日の数日前を確認すると爆発している様子は見られません。
そこで、Fluentdコンテナのログを確認してみると以下のようなエラーログが発生しており、2.の状態であると確信しました。

以下のようなサイクルが発生すると考えれば納得ができます。

1. Fargateタスクがデプロイされる
2. Fluentdコンテナ以外が正常に起動する
3. Railsコンテナのfluentd_gemがログをバッファに貯める
   • この間は正常にリクエストが実行される
4. Railsコンテナのfluentd_gemがバッファをフラッシュしようとするが、Fluentdが受け取れないので待つ
5. 30秒経過し、ターゲットグループのヘルスチェックに失敗しコンテナがDrainされる
6. 1．に戻る

ここまで調べて、「もしかしてRenovateによってFluentdがアップデートされたのでは？」と思い調べ直すと、障害発生日当日のリリースに含まれていました。
そこで、Fluentdのアップデートを切り戻すリリースを行ったところ事象が再発することなく、問題は収束しました。

根本原因の特定

今回の事象の原因は、Fluentdがバージョンアップされたことに伴いライブラリが正常に動作しなくなったためということがわかりました。
実際に、どのライブラリが正常に動作しないのかを確認するため、ローカルでの動作検証を行ってくれたエンジニアがいるのですが特定には至ってません。

現時点では、まだどのライブラリが原因かまでは突き止めることができていないため、引き続き調査を続けていこうと考えています。

恒久対応としての監視改善

今回の直接的な原因としてはFluentdのアップデートによるものですが、今まで存在していた各種アラートのしきい値をくぐり抜けたことが問題です。
「今までの設定が悪い」ということではなく、今回ここで顕在化してくれたことと大規模にサービスを停止させるような状況にならなかったことに感謝しつつ監視内容を改善します。

具体的には次のように改善しました。

ログ監視の改善

実は改めて確認していると、NewRelicに対してRailsアプリケーションがFluentdにログを送信できない旨のエラーがERRORで通知されていました。
( これを見落としていたのは結構痛手でした )

当初はCloudWatch LogsでFluentdコンテナが正常に起動できていないログを検知できたら通知することを考えていましたが、弊社では現在AWSからGoogleCloudへの移行を行っていることと、上記の結果から、NewRelicでのログ監視を強化することにしました。

Fluentdのエラーに絞っても良いことはあまり無いのと、今後チューニングすれば良いとの考えで、次のようなNRQLを使ってアラートを作成することにします。

SELECT `level`,`message`
FROM Log
WHERE `entity.name` = 'YOUR_ENTITY_NAME'
AND `level` = "ERROR"

メトリクス監視の改善

上述のログ監視だけでは、特定コンテナの異常には気づけますがその他のコンテナの異常には気づけません。
できれば普遍的に扱えるメトリクスを監視したいと思ったところ、UnHealthyHostCountメトリクスがNewRelicに送信されているため、こちらを使って監視内容をアップデートします。

具体的には以下のようなNRQLになります。

SELECT
  max(aws.applicationelb.UnHealthyHostCount) AS UnHealthyHostCount
FROM Metric
WHERE aws.applicationelb.TargetGroup LIKE 'targetgroup/TARGET_GROUP-%'

また、CloudWatchではALBの5XX系エラー数をトリガーとする監視を設定していましたが、こちらのしきい値がかなり高く、サービス全断レベルで5XX系エラーを返さないとアラートとして機能しないこともわかりました。
そのため今回の件を持って、しきい値を低く設定することで今回のような「ちょっとずつ異常が発生する」ようなケースにも対応できるようになりました。

その他の改善

弊社ではNewRelicを使っており、導入当初の段階ではterraformによるIaCはなされていたものの最近は放置されがちでした。
これはダッシュボードの生成などをGUIで行っていることが多く、IaCとの相性が悪いからなのですが、今回を良い契機と捉えて上記の監視類はmodule化しIaC化を促進しようと考えました。

module自体は割愛しますが、ダッシュボードのIaC化も考えはじめているため今回のおかげで監視の改善が捗りそうです。

今回の学びとまとめ

今回、ユーザー様にはご迷惑をおかけしていた可能性が高いというのは申し訳ない点ではありますが、アラートなどが発生していないサイレント状況下においてレスポンスタイム悪化の検知から改善までかなりスピーディに対応できたと考えています。

初手から全ての事象を想定し見るべきメトリクスやアラートを設定することができれば良いのですが、システムは成長していくため、すべてを想定することは難しいと考えています。
そのため、システムが正常に動作し続けていた場合でも定期的に監視体制を見直し、潜在的な不備を発見・改善していく必要があります。今回のトラブルは、そういった見直しの重要性を改めて体感する良い機会となりました。

最後に、個人的な反省点を述べて終わりにしたいと思います。

• 普段見慣れているメトリクスだけ見ていたこと
• 特定の監視ツールによらず、もっと幅広く見るべきだった
• アプリケーションの変更だけに目が向きすぎたこと
  • アプリケーション以外のアップデートを見ていなかったこと
  • サイドカーコンテナの状態を見ていなかったこと
• せっかくFargate上でエラーが見れる状態だったのに上記から見るのが遅れてしまったこと

最後までご覧いただき、ありがとうございました。