tkzwhr's notes

tkzwhrの技術、中国語などのメモです。

Cloudwatch Logs Insightsの活用事例

Tech

11/27にリリースされた新機能Cloudwatch Logs Insightsが障害調査を進める上で有用だったため紹介したい。

Cloudwatch Logsの課題

AWSのイベントログやその他のログ等を管理するサービスとしてCloudwatch Logsは有用であるが、実際にサービス運用を始めて、データ量が増えてくるにつれて、だんだんと使いづらい部分が見えてくる。

  • 障害の発生状況を細かく条件設定して見る
  • ログから障害の傾向を分析したいが、集計するのが億劫

もちろんアラームでログ監視をする方が効果的な場合もあるが、今回はCloudwatch Logs Insightsで効率的に分析できた事例を紹介する。

Cloudwatch Logs Insightsとは

誤解を恐れず言うと、Cloudwatch Logsに対してデータベースのようにクエリを発行して検索できる機能と思っていただければ良い。

料金はデータのスキャン量に対しての従量課金で、1GBあたり0.005ドルとなっている。 不用意にスキャンしすぎないように、スキャン対象を日時で絞る必要がある。

Case1. エラーの原因を切り分ける

事象

ログを斜め読みしていたら、とあるAPIでエラーが頻発していたので、下記のクエリを流してみた。

fields @message
| filter @message LIKE "ERROR"

クエリのポイントは下記の通り。

  • fields <A>を使うとAの内容を出力することができる
  • filter <A> LIKE <B>でAの内容からBの内容を部分一致検索できる
  • @messageはログ本文の変数である

結果は下記の通り。

f:id:tkzwhr:20201108221021p:plain

この期間だけで3,950行あることが分かる。

調査

下側に表示されたリストの内容をざっとみたところ ECOM-403-001 というエラーが多く発生していそうであったため、一旦検索対象から外してみた。

fields @message
| filter @message LIKE "ERROR"
| filter @message NOT LIKE "ECOM-403-001"

f:id:tkzwhr:20201108221338p:plain

...2件！ 実は ECOM-403-001 以外のエラーがほとんど発生していないことが判明した。

対策

ECOM-403-001 についてはクライアント側の問題、かつ、クライアント側での対処方法が明確なエラーであったため、検知しないようにすべくエラーのレベルを引き下げる対応を19:30ごろに行った。

翌日、再度エラー発生状況の集計を行った。

fields @message
| filter @message LIKE "ERROR"

結果は下記の通り。

f:id:tkzwhr:20201108221346p:plain

明らかに19:30を境にエラーが出てこなくなっていることが確認できた。

Case2. 対策の効果を計測する

事象

しばらくすると、とあるAPIについて、API Gatewayから413 Request Entity Too Largeエラーが返却されてくるようになった。

とあるAPIのログを見ると、確かにエラーとなっているログが存在していた。 ログを確認すると、カスタムヘッダ x-cookie の値が異様に長くなっているものがエラーになっていることが判明した。 結果的には呼び出し側のアプリの問題であることが分かり修正したが、修正後はどのような経過になっているのか調査することにした。

Cloudwatch Logs Insightsでの確認

下記のようなクエリを発行した。

問題発生 （アプリ v4.0.3）

fields strlen(`headers.x-cookie`) as CookieLength, floor(CookieLength/100)*100 as AmbiguousCookieLength
| filter `headers.x-app-version` = "4.0.3"
| stats count(AmbiguousCookieLength) as AmbiguousCookieLengthCount by AmbiguousCookieLength
| sort AmbiguousCookieLength desc

集計期間 11/28 17:00:00 〜 17:59:59

f:id:tkzwhr:20201108221353p:plain

対策後 （アプリ v4.0.4）

fields strlen(`headers.x-cookie`) as CookieLength, floor(CookieLength/100)*100 as AmbiguousCookieLength
| filter `headers.x-app-version` = "4.0.4"
| stats count(AmbiguousCookieLength) as AmbiguousCookieLengthCount by AmbiguousCookieLength
| sort AmbiguousCookieLength desc

集計期間 11/29 17:00:00 〜 17:59:59

f:id:tkzwhr:20201108221401p:plain

クエリのポイントは下記の通り。

  • strlen <A>を使うとAの文字数を数えることができる
  • <A> as <B>でAにBという名前を付けられる
  • floor(<M>/<N>)*<N>でMをN単位の概算値に変換する（今回はN=100）
  • stats count(<A>) by <A>でAごとの合計を集計する
  • sort <A>を使うとAを昇順(asc)か降順(desc)で並び替えられる
  • head <N>を使うと上位N個分のデータを取得することができる

2つを見比べ、この対処により改善されていることが分かった。

ランキング集計してダッシュボードで確認する

次に、今後も長くなっているものがあれば見つけやすいようにランキングを表示するクエリを発行した。

fields @requestId, strlen(`headers.x-cookie`) as CookieLength
| filter `headers.x-app-version` = "4.0.4"
| sort CookieLength desc
| limit 10

f:id:tkzwhr:20201108221407p:plain

requestIdを表示しておき、必要に応じてログを調査できるようにした。

あとは、「ダッシュボードに追加」ボタンを押せば、好きなダッシュボードに追加して監視することができる。

f:id:tkzwhr:20201108221412p:plain

Case3. 運用でのリカバリを考える

事象

サーバサイドの不具合で、11/28にログインしたユーザについては、メールアドレスが正しくなく、その後の使用でデータ不整合を起こす可能性があることが判明した。 影響を受けるユーザを抽出する必要が出てきた。

Cloudwatch Logs Insightsでの確認

調査した結果、 - 11/28にログインしたユーザについては、メールアドレスがdummy@example.comになっている - bodyに含まれるaccountNoでユーザを一意に特定できる ことがわかったため、メールアドレスがdummy@example.comになっているユーザのaccountNoを抽出することにした。

現状、AWSのコンソールではクエリの結果をファイルにエクスポートすることができないため、AWS CLIを使う。

start-queryコマンドでクエリ発行を行う。クエリ発行に成功するとqueryIdが返却されてくる。

$ aws logs start-query --log-group-name="/aws/lambda/foobarApi" --start-time=0 --end-time=1543755820 --limit=10000 --query-string='fields @timestamp, body.accountNo | filter body.email = "dummy@example.com" | filter @timestamp > 1543330800000 | filter @timestamp < 1543417199000 | limit 10000'
{
    "queryId": "00000000-c482-48c8-9968-b256593f0b69"
}

get-query-resultsコマンドでjsonを取得できるので、csvに変換してリスト化した。

$ aws logs get-query-results --query-id="00000000-c482-48c8-9968-b256593f0b69" > results.json
$ cat results.json | jq -r '.results[] | [.[0].value, .[1].value] | @csv' > results.csv

コマンドラインから実行する場合の留意点

  • start-time, end-timeはGMT（日本ならば-9時間した時間）を秒の単位で指定する（クエリの中の変数はミリ秒単位なので、間違えないように）
  • 現状はスキャン対象を絞るためのパラメータがないため、全件スキャンになってしまう
  • limitを省略すると1000件までの取得となる
  • limitはパラメータだけでなくクエリにも必要である
  • limitの上限は10,000件になっている

気になったこと

  • ログが分割されていると分析がしづらい
    • 1トランザクションのログの行が複数行ある場合でも、検索対象の行しか見られないため、例えば「レスポンスがエラーになっているトランザクションのリクエストのログを確認する」と言ったことはやりづらい
    • 活用しやすいようなログ出力設計が必要かもしれない
  • 結果のファイル出力が弱い
    • クリップボードにコピーする機能はあったりするが、検索結果が大きくなってくるとマシンの負荷が高くなりなかなか難しくなってくる
    • 今回はAWS CLIでやれる範囲だったが、使い勝手やコンソールと比べても機能が弱いので今後の改善に期待したい
  • ダッシュボードに貼り付けると定期的に実行される
    • 検索範囲は絞ることができるが、定期的にクエリが実行されていることを忘れると思わぬ料金になったりする可能性がある
    • ダッシュボードの更新頻度は確認しておいたほうが良い
  • クエリの同時実行数が4である（数値は今後変わるのかもしれないが）
    • ダッシュボードに貼り付けると定期的に実行されるため、ダッシュボードに結果を貼りまくっていると、いざコンソールからクエリを流そうとしたときに実行エラーになることがある
  • ロググループを横断する調査についてはどうすればいいのか分からない
    • これもログ出力設計になるのだろうか...勉強中である

まとめ

エラー調査では、CloudWatchの検索窓から頑張って検索するか、アラーム設定するかで乗り切っていたが、特定の時間にだけ多く発生しているエラーがあるのかどうかとか、どんなエラーが多く発生しているのかとか、集計したいと思うときが多く、そこそこ限界を感じていたので、いいサービスだなと思った。