【ITニュース解説】Finally Pinpointed Intermittent Staging Failures with AI Log Analysis

ITシステムを開発する現場では、様々な環境が使われる。その中でも「ステージング環境」は、開発したプログラムが本番環境と同じように動くかを確認するための、非常に重要な場所である。しかし、このステージング環境で「断続的に発生する障害」は、システムエンジニアにとって頭を悩ませる最も困難な問題の一つである。今回のニュース記事は、まさにそのような手のつけられない問題が、どのような思考プロセスと技術によって解決されたのかを具体的に示している。

記事で語られている問題は、マイクロサービスと呼ばれる、多数の小さなプログラム（サービス）が連携して動く複雑なシステムで起きた。このシステムでは、データベース、メッセージをやり取りするKafka、高速なデータアクセスを提供するRedisなど、多くの部品が組み合わさって機能している。通常は問題なく動作するはずのこのステージング環境で、数日に一度、特に開発者が多く利用する時間帯に、いくつかの重要なサービスが突然「Connection refused by upstream（接続拒否）」や「Service Unavailable（サービス利用不可）」といったエラーを出し始めた。このエラーは5分から10分ほど続いた後、何事もなかったかのように自然に解消されるという、なんとも掴みどころのない現象だった。新しいプログラムの導入が原因でもなく、システムの負荷が急増したわけでもない。「幽霊」のような障害であり、開発チームのデプロイ（プログラムの導入）を妨げ、多大なフラストレーションを与え続けた。

このような「断続的な障害」のデバッグは非常に難しい。開発者のパソコン上で同じ状況を再現しようとしても発生せず、ステージング環境に意図的に高い負荷をかけても、必ずしもエラーが再現するわけではなかった。まるでシャイなバグのように、都合の良い時にだけ現れる。チームは、ログと呼ばれるシステムが記録する動作履歴を確認したり、サービスを再起動したりと、できる限りの手を尽くしたが、結局は自然復旧するのを待つしかなかったという。

筆者はまず、ログを徹底的に調べ始めた。これはデジタル世界における探偵の仕事に似ているが、地図のないまま膨大な手がかりをたどるようなものだった。数ギガバイトにも及ぶ構造化されたJSON形式のログを手作業で読み解き、特定のキーワードで検索したり、時間を合わせてサービス間のログを比較したりと、2週間近くを費やした。エラーの発生頻度を数えるための簡単なスクリプトも書いたが、ログの量があまりにも多く、また障害の発生が不定期であるため、結局は文字の洪水に飲み込まれ、解決の糸口は見つけられなかった。

システムの状態を監視するツールとして、PrometheusとGrafanaという高機能なツールも導入されていた。これらはCPUの使用率、メモリの使用量、ネットワークの通信量などをダッシュボードに表示してくれるが、障害が発生する直前に、特に目立った異常は記録されていなかった。CPU使用率がわずかに上昇することはあっても、それ自体が問題を示すほどではなかった。そこで、メモリリーク（プログラムがメモリを解放し忘れ、徐々にメモリを使い切ってしまう現象）を疑い、問題のあるサービスのリソース（メモリやCPU）を増やしてみたが、結果は変わらなかった。チーム全員で主要なサービスのコードを詳細にレビューし、複数の処理が同時に行われる際に発生しうる競合状態や、予期せぬ並行処理の問題がないかを探したが、ここでも解決には至らなかった。

人間が手作業で膨大なログの中から関連性を見つけ出すことに限界を感じた筆者は、考え方を変えた。自分の脳が、特定の情報に偏ってしまい（確証バイアス）、またログの量に圧倒されて見過ごしてしまうような「点と点」を、機械ならつなぎ合わせられるのではないかと考えたのだ。本格的なログ分析システム（ELKスタックなど）を構築する時間も、高価な商用ソリューションを導入する予算もなかったため、自分で簡易的な仕組みを作ることを決意した。

彼が「AI」と呼んだものは、実際にはPythonで書かれた特定のスクリプトだった。このスクリプトは以下のように動作した。まず、Kubernetesというシステムで動作するサービス群から、毎時間ごとに過去1時間分のログを自動的に集め、Fluentdというツールを使ってS3というクラウド上のストレージにJSON形式で保存した。次に、PythonスクリプトがS3からこれらのログをダウンロードし、JSONデータを読み込んで、pandasというライブラリを使って「タイムスタンプ」「サービス名」「ログレベル（情報、警告、エラー）」「メッセージ」といった要素に構造化し直した。

このスクリプトの「AI」部分は、統計的に意味のある「共起（一緒に発生すること）」を探すことに焦点を当てた。深層学習のような複雑なものではなく、シンプルだが賢いパターンマッチングである。具体的には、30秒、60秒、120秒といった「時間窓」を設定し、「特定のサービス（今回の場合、order-processor）でエラーメッセージが出現する前に、他のどのサービスから、どのような『警告（WARN）』や『情報（INFO）』メッセージが、高い頻度で発生しているか？」という問いに答える仕組みだ。スクリプトは、ログを時間窓でグループ化し、異なるメッセージの種類を数え、order-processorでエラーが発生するたびに、その時間窓内で他のサービスから出現したメッセージを遡って調査した。

このスクリプトを数日間実行し、その結果を分析したところ、筆者が見落としていたパターンが浮かび上がった。order-processorで発生する「Connection refused by upstream」エラーのほぼ全てが、約45秒前にnotification-serviceという別のサービスから発せられた特定の「WARN」メッセージによって先行されていたのだ。そのメッセージは、「KafkaProducerException: TimeoutException: Failed to send; it took 60000ms. Message buffer full.（Kafkaへのメッセージ送信に失敗、バッファが一杯になった）」という内容だった。

これはnotification-serviceにとっては「エラー」ではなく単なる「警告」だったため、人間の目では重要視されず、見過ごされていた。しかし、スクリプトは、この警告がorder-processorのエラーと統計的に強く関連していることを発見した。つまり、notification-serviceがKafkaにメッセージを送れなくなり、その内部バッファがいっぱいになると、notification-service自体が一時的に応答不能になり、それに依存しているorder-processorが接続エラーを起こしていたのである。問題の原因はorder-processorではなく、notification-serviceのKafkaプロデューサー（Kafkaへメッセージを送る機能）のボトルネックにあったのだ。

この発見に基づき、二つの対策が講じられた。一つは、notification-serviceのKafkaプロデューサーの設定を変更し、メッセージを一時的に保持するバッファの容量を増やし、タイムアウト時間を延長したことだ。これにより、一時的なKafkaの問題や大量のイベントが発生しても、メッセージが適切に処理されるようになった。もう一つは、order-processorがnotification-serviceを呼び出す際に、「サーキットブレーカー」というパターンを導入したことである。これは、notification-serviceが応答しない場合に、order-processorがすぐに処理を中止してエラーを返し、しばらく待ってから再試行するという仕組みで、無駄な待機を防ぎ、システム全体の安定性を向上させた。

このログ分析スクリプトの開発には、約3日間のコーディングと調整が費やされたという。しかし、その結果は劇的で、ステージング環境の安定性はピーク時の稼働率が約60%から98%以上にまで改善し、その後1週間、問題なく稼働している。この事例は、最も複雑に見える問題が、必ずしもより強力な（高価な）ツールを導入することで解決するとは限らず、既存の膨大な情報の中から、人間では見つけにくいパターンを賢く自動で探し出すことで解決できることを示している。そして、システムエンジニアにとってログ分析がいかに重要であるかを改めて浮き彫りにした。