CloudWatch Logsの障害調査をgrepからLogs Insightsクエリに変えた境界線

障害対応でCloudWatch Logsを追うとき、まずgrepで済ませていました。ですが、ある決済APIのタイムアウト調査で、5分間に3万行出るログを目で追うのが限界になりました。リクエストIDはあるが、どのリクエストが遅いのか、リトライが何回重なったのかがgrepでは見えない。そこでLogs Insightsのクエリを調査手順に組み込みました。

まず、ロググループをまたぐ前提で、共通のフィールド名を決めます。アプリ側で request_id, route, status, duration_ms, attempt をJSONで出している場合、次のクエリで遅いリクエストの上位が出せます。

fields @timestamp, request_id, route, status, duration_ms
| filter route = "/v1/payments" and duration_ms > 1000
| sort duration_ms desc
| limit 20

リトライの重なりを見たいときは、request_idで集計します。

fields request_id, attempt, duration_ms
| filter route = "/v1/payments"
| stats count(*) as attempts, max(duration_ms) as max_ms by request_id
| filter attempts > 1
| sort max_ms desc
| limit 20

これを障害対応の最初の5分で流すようにしました。grepで全文を眺めるより、外れ値のrequest_idを特定するのが速い。特定したIDで再度絞り、前後のログを時系列で並べます。

fields @timestamp, level, message, attempt, status
| filter request_id = "req-xxxx"
| sort @timestamp asc

なぜこれでうまくいったかというと、調査の目的が「件数を数える」から「異常な1件を特定する」に変わったからです。grepは全文一致には強いが、集計には向きません。Logs Insightsはスキャン量に課金されるので、時間範囲を絞らないとコストが跳ねます。私は最初、24時間範囲で雑に流して、不要なスキャンで余計に費用を使いました。今は必ず直近15分から始め、必要なら広げる順番にしています。

失效する境界もあります。ログがJSONで構造化されていないと fields が効かず、結局grepに戻ることになります。また、複数サービスをまたぐとrequest_idが伝播していない箇所があり、そこはクエリでは埋まりません。私が踏んだのは、リトライ回数を attempt で出していたのに、別のクライアントだけ retry_count という名前で出していて、集計から漏れていたケースです。フィールド名の統一はクエリを書く前にやるべきでした。

皆さんの環境では、遅いリクエストを特定するとき、最初にどのフィールドで絞っていますか。request_idか、ユーザーIDか、routeかで、クエリの形がかなり変わるはずです。