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
はログ本文の変数である
結果は下記の通り。
この期間だけで3,950行あることが分かる。
調査
下側に表示されたリストの内容をざっとみたところ ECOM-403-001
というエラーが多く発生していそうであったため、一旦検索対象から外してみた。
fields @message | filter @message LIKE "ERROR" | filter @message NOT LIKE "ECOM-403-001"
...2件!
実は ECOM-403-001
以外のエラーがほとんど発生していないことが判明した。
対策
ECOM-403-001
についてはクライアント側の問題、かつ、クライアント側での対処方法が明確なエラーであったため、検知しないようにすべくエラーのレベルを引き下げる対応を19:30ごろに行った。
翌日、再度エラー発生状況の集計を行った。
fields @message | filter @message LIKE "ERROR"
結果は下記の通り。
明らかに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
対策後 (アプリ 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
クエリのポイントは下記の通り。
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
requestIdを表示しておき、必要に応じてログを調査できるようにした。
あとは、「ダッシュボードに追加」ボタンを押せば、好きなダッシュボードに追加して監視することができる。
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件になっている
気になったこと
- ログが分割されていると分析がしづらい
- 結果のファイル出力が弱い
- ダッシュボードに貼り付けると定期的に実行される
- 検索範囲は絞ることができるが、定期的にクエリが実行されていることを忘れると思わぬ料金になったりする可能性がある
- ダッシュボードの更新頻度は確認しておいたほうが良い
- クエリの同時実行数が4である(数値は今後変わるのかもしれないが)
- ロググループを横断する調査についてはどうすればいいのか分からない
- これもログ出力設計になるのだろうか...勉強中である
まとめ
エラー調査では、CloudWatchの検索窓から頑張って検索するか、アラーム設定するかで乗り切っていたが、特定の時間にだけ多く発生しているエラーがあるのかどうかとか、どんなエラーが多く発生しているのかとか、集計したいと思うときが多く、そこそこ限界を感じていたので、いいサービスだなと思った。