地味にイイネ!Amazon CloudWatch Logs Insightsで効率的に調査しよう!

こんにちは。アーキテクトの青木です。

イイデスネ、CloudWatch Logs Insights。

GAしてからもうすぐ1年ぐらい立つので使っている方も結構いるのではないかと思います。 これを使うとアプリケーションのトラブルシュートが手軽にできるようになります。

この前使ってみて結構便利だったので、記事にしてみます。

いざ、障害になったときに慌てないように準備しておきたいですね。

CloudWatch Logs Insightsとは

CloudWatch Logs Insights は、CloudWatch Logs にたまったデータを分析・集計することができます。 ロググループと日時を指定し、専用のクエリを実行すると集計結果がでます。

さまざまな検索条件をつけられますので、お望みのデータをズバンと抽出することが簡単にできます。 さらに集計した結果をダッシュボードで可視化することができます。

ざっくり使い方を見てみる

CloudWatch Logs Insightsは、GUIがそれなりに使えるようになっていますので、 AWS コンソール上で叩きます。

それではログをある条件で検索して、ダッシュボードに可視化する方法を見ていきましょう。

1. ロググループと範囲を指定

まずは原因調査したいロググループを指定します。 運用が長くなるとロググループが猛烈に増えてしまうのですが、サジェストできるので見つけやすいです また、ロググループは複数設定が可能です。横串で同時検索するシチュは結構あるので非常にありがたいです!

つづいて日付範囲を指定します。 右上メニューで直近1時間や6時間を指定します。カスタムで範囲を広げることもできます。

f:id:ecb_yaoki:20190909121555j:plain
ロググループと範囲を指定

ここで1点注意ですが、Athenaと同様、スキャンデータ量による課金です。 範囲を広げすぎると、想定以上の請求が来る可能性があるので、ご注意ください。

料金は下記です。

aws.amazon.com

2. 検索する

クエリの中身は後述するとして、とりあえず「クエリ実行」します。 すると、指定したロググループと範囲をスキャンして結果が返ります。

下記例では、ためしにElastic Beanstalkで出力している、IISのアクセスログを検索して表示した結果です。

ちょっとモザイク多いですが、検索結果にIP、URL、StatusCode等が出力されています。 グラフも出力されていて、何時にどれだけのアクセスログが出力されているかも一発でわかるのでわかりやすいです。

f:id:ecb_yaoki:20190909152629j:plain
検索結果

スキャン結果も表示されています、併せて目安にすると良いと思います。

8,292 個のレコードが一致しました | 10,856 個のレコード (2.2 MB) 2.8秒でスキャン @ 3,931 個のレコード/秒 (806.8 KB/秒)

3. ダッシュボードに可視化する

さらに、クエリした結果をCloudWatchのダッシュボードに表示することができます。 アクションからダッシュボード追加で設定します。

f:id:ecb_yaoki:20190917100356j:plain
ダッシュボード追加

ダッシュボード追加すると、一覧形式やグラフ(線)など、ウィジェットタイプから選択します。 しばらく経過観察したいログなどは、ダッシュボードに登録しておくと良さそうですね。

f:id:ecb_yaoki:20190917100808j:plain

クエリの仕様について

簡単な使いかたは以上です。 少しとっつきにくいかもしれないのが専用クエリですね。 まずは、初期表示に出てくるクエリを見ていきましょう。

これはGUIで設定したロググループと日付範囲を対象に、最新20件を取得する命令です。 ぱっと見わかりにくいですが、SQLで言うところの fieldsselectsortorder byのように読み置き換えているとわかりやすいです。

fields @timestamp, @message
| sort @timestamp desc
| limit 20

コメント一覧を並べると下記のとおりです。 取得したい項目はfields指定して、filterで検索条件指定して、statsで集計してと、 SQLの全部とは言わないまでも、だいたいのやりたいことは実現できそうですね。

fields・・・SQLでいうSelectです

filter・・・SQLでいうWhereです。論理演算子(And, Or, No)や比較演算子、Likeで正規表現での絞り込みも対応しています。

sort・・・SQLでいうOrder Byです

limit・・・SQLでいうLimitです

stats・・・avg(), sum(), count(), max(), min()といった集計関数を使うことができます

parse・・・ログメッセージのparseができます。parseした項目をfieldsfilterで利用します。

細かいところは、下記参照いただければと思います。 docs.aws.amazon.com

fieldsで利用可能な変数について

filterで使える変数は、@timestamp、@logStream、@messageがどのログタイプでも使えます。 それ以外にも、LambdaやCloudTrail ログなど特定のログタイプは、追加で専用変数が用意されています。 他にどのようなログタイプがあるかは下記を参照してください。

docs.aws.amazon.com

たとえばLambdaですと下記の通りです。 基本の@messageだけじゃなく、@duration@maxMemoryUsedといった項目が利用可能です。 「検出されたフィールド」項目に自動で変数が表示されるので、何となく分かるかと思います。

f:id:ecb_yaoki:20190909191000j:plain

クエリについて

クエリは手軽に利用しやすいようにサンプルクエリがあります。 用途によってカスタマイズするのがよさそうです。

f:id:ecb_yaoki:20190910192201j:plain
サンプルクエリ

下記にすぐ使えそうなクエリをいくつかピックアップしておきます。

1. エラーを調べる

例外やエラーの文字列を抽出します。 @logStreamをつけておくと、Logs Streamへダイレクトジャンプできます。 前後のログが確認できるので便利です。

fields @timestamp, @message, @logStream
| filter @message like /(?i)(Exception|Error)/
| sort @timestamp desc
| limit 100

2. 5分ごとに記録される例外の数を調べる

サンプルクエリの中にあります、「5分ごとに記録される例外の数」です。 エラーの頻発具合をぱっと把握できるので便利です。

filter @message like /Exception/
| stats count(*) as exceptionCount by bin(5m)
| sort exceptionCount desc

結果がこちらです。このように視覚的にもわかりやすく表現してくれます。

f:id:ecb_yaoki:20190910194109j:plain

3. アクセスログのテキストをparseして検索する

@messageで強引に絞り込みするのが辛い局面では、一度parseして絞り込むようにします。 例えば、下記のようなスペース区切りで構成しているアクセスログの場合です。

HTTPステータスコードを500で絞りたいと思ったときに、 他の文言がヒットして想定しないレコードも併せて取得してしまう場合があります。

<アクセスログ(IISログ)>

xxx.xxx.xxx.xxx GET /xxxxx/xxxx/xxx xx=1234500&yy=67890 80 - xxx.xxx.xxx.xxx user-agent - 200 0 0 125
xxx.xxx.xxx.xxx POST /xxxxx/xxxx/xxx - - xxx.xxx.xxx.xxx user-agent - 500 0 0 125
xxx.xxx.xxx.xxx GET /xxxxx/xxxx/xxx xx=12345&yy=67890 80 - xxx.xxx.xxx.xxx user-agent - 200 0 0 125

このような場合、一旦parseしたものをfilterで絞り込むようにします。 parseは、正規表現とglobが対応していますので、やりやすい方で記述してください。

<クエリ 正規表現版>

fields @timestamp
| parse @message /^(?<c_ip>.+?)\s(?<cs_method>.+?)\s(?<cs_uri_stem>.+?)\s(?<cs_uri_query>.+?)\s(?<s_port>.+?)\s-\s(?<s_ip>.+?)\s(?<cs_user_agent>.+?)\s-\s(?<sc_status>.+?)\s(?<sc_bytes>.+?)\s(?<cs_bytes>.+?)\s(?<time_taken>.+?)/
| filter sc_status = 500
| sort @timestamp desc
| limit 20

<クエリ glob版>

fields @timestamp
| parse @message "* * * * * - * * - * * * *" as c_ip, cs_method, cs_uri_stem, cs_uri_query, s_port, s_ip, cs_user_agent, sc_status, sc_bytes, cs_bytes, time_taken
| filter sc_status = 500
| sort @timestamp desc
| limit 20

検索結果は下記の通り、parseされた項目がそれぞれ出力されます。

f:id:ecb_yaoki:20190917121817j:plain
parseしたクエリ

まとめ

CloudWatch Logs Insightsは専用クエリが嫌で積極的に使っていなかったのですが、 実際は食わず嫌いなだけでしたね(笑)

CloudWatch Logsにログを溜め込んでいるなら、まずはInsightsで対応できないか検討すべき。

いつ起きるかわからない障害を いざというときに効率的に正確な情報を早く集められるように、日頃から準備しておきたいですね。

それではまた


~ecbeingでは地味にいいツールやTipsを使いこなしてエンジニアリングライフをハックする、イケてるエンジニアを大募集中です!~ careers.ecbeing.tech