health checkを除外してCloudWatchのログを眺めたい。 #AWS

やりたいこと

表題の通りです。

なぜ？

小さなシステムの動作チェックを担当した際に、ログ周りはCloudWatchに書き出されているので、手っ取り早くそちらを眺めました。
でも、health checkのログが多すぎて本来見たいログが埋もれてしまって悲しかった、というのが背景です...。

前提条件

AWSの管理コンソールから見るのではなく、awslogsコマンドで手元のターミナルで見たい
health checkっぽいのは除外したい
health checkを叩いてくるのはロードバランサ (ELB）
ヘルスチェックのログ出力自体は、まだ調整中なので抑止せずに書き出しておきたい（わがままで申し訳ないです...）
Filter options (--filter-pattern) を使って絞り込む
- https://github.com/jorgebastida/awslogs#filter-options
- ただし、この場合は「除外」のフィルタ条件にしたい

やってみる

Nginxのログっぽいもので試します。

ただし、ログは実際のアプリケーションからのログではなく、シェルスクリプトでロググストリームに突っ込むという方式でテストします
- CloudWatchのロググループに手動でテスト用ログを投入したい。

awslogsのコマンドラインオプションはこの通り。

-S オプションは、出力行にロググループ名を添えない（長くなるので）
-G オプションは、出力行にログストリーム名を添えない（長くなるので）
awslogs get ロググループ名 (ロググループ名まで指定の場合)
awslogs get ロググループ名 ログストリーム名 (ログストリーム名まで指定の場合)

お試しデータのスクリーンショット

実験: フィルタ無し

CloudWatch上に /TestLogGroup というロググループを作成しています
さらに、TestStream というログストリームにログを書き出しています
-s 1m で直近1分のものを出力します

$ awslogs get /TestLogGroup TestStream -s 1m --aws-region="ap-northeast-1"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:50:54+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 192.0.2.10 - - [2020-05-16T11:50:56+0900] "GET /test/health_check HTTP/1.1" 200 25 "-" "ELB-HealthChecker/2.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:50:58+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 192.0.2.10 - - [2020-05-16T11:51:00+0900] "GET /test/health_check HTTP/1.1" 200 25 "-" "ELB-HealthChecker/2.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:51:03+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 192.0.2.10 - - [2020-05-16T11:51:05+0900] "GET /test/health_check HTTP/1.1" 200 25 "-" "ELB-HealthChecker/2.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:51:07+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 192.0.2.10 - - [2020-05-16T11:51:09+0900] "GET /test/health_check HTTP/1.1" 200 25 "-" "ELB-HealthChecker/2.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:51:11+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 192.0.2.10 - - [2020-05-16T11:51:13+0900] "GET /test/health_check HTTP/1.1" 200 25 "-" "ELB-HealthChecker/2.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:51:15+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
....

実験: フィルタあり

--filter-pattern='-"ELB-HealthChecker/2.0"' を添えて、ELBからのヘルスチェックを除外してみます。

ポイントは、 - (マイナス) で除外パターンを指定している点です。

awslogs get /TestLogGroup TestStream -s 1m --aws-region="ap-northeast-1" --filter-pattern='-"ELB-HealthChecker/2.0"'

# 結果が絞りこまれました！
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:56:46+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:56:50+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:56:55+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:56:59+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:57:04+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:57:08+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:57:13+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:57:18+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:57:22+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
/TestLogGroup TestStream 198.51.100.2 - - [2020-05-16T11:57:28+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"

オプションを調整してスッキリさせてみる

ロググループがわかっている、ログストリームは明示していなくても該当のロググループ内の最新のイベントで確認するだけでいい場合は、

-G (グループ名を表示しない）
-S (ストリーム名を表示しない）

オプションでもう少しスッキリします。

$ awslogs get /TestLogGroup -s 1m --aws-region="ap-northeast-1" -S -G --filter-pattern='-"ELB-HealthChecker/2.0"'

198.51.100.2 - - [2020-05-16T12:03:49+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
198.51.100.2 - - [2020-05-16T12:03:54+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
198.51.100.2 - - [2020-05-16T12:03:59+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"

あらためて

さて、上記でやりたいこととやったことを書いてしまいましたが、後々のことを考えて、自分のためのメモを添えます。

awslogsについて

AWS CloudWatch logs for Humans™ というキャッチコピーがリポジトリに書かれていますが、まさに大助かりです...。

リポジトリ: https://github.com/jorgebastida/awslogs
pythonで書かれいます

Issueやプルリクエストも多く、Pythonで書かれているし、基本は更新系でなくapiからの取得と出力なので、OSSの素材としても良さそう！

除外パターンを複数指定したり組み合わせる場合は？

基本はCloudWatchのフィルタパターンに対応した書き方で値を渡します。

https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/FilterAndPatternSyntax.html

/test/health_check, HealthCheck の双方を含むケースを除外

- (マイナス) をつけた条件を列挙します

--filter-pattern='-"/test/health_check" -"HealthCheck"'

POSTを含むイベントを抽出したい場合

--filter-pattern='POST'

POSTを含むイベントのうち特定のエンドポイントは不要

条件を列挙しますが、除外の条件は -"条件パターン" を添えます

--filter-pattern='"POST" -"/endpoint_to_ignore"'

どれかのパターンを含むイベントを抽出したい場合

キーワードの前に?を添えます

--filter-pattern='?index ?health'

どれかのパターンを含むイベントのうち、あるパターンは除外したい場合

ORの条件の後に、-"除外パターン" を添えます
以下だと、index.html か /test/health_check　を含む行はヒットしますが、そのうち 12:05台のイベントは除外されます

awslogs get /TestLogGroup -s 10m --aws-region="ap-northeast-1" -S -G -filter-pattern='?index ?health -"T12:05"'

# 出力例 (T12:05は除外)
.....
198.51.100.2 - - [2020-05-16T12:04:52+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
192.0.2.10 - - [2020-05-16T12:04:54+0900] "GET /test/health_check HTTP/1.1" 200 25 "-" "ELB-HealthChecker/2.0" "-"
198.51.100.2 - - [2020-05-16T12:04:58+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
198.51.100.2 - - [2020-05-16T12:06:02+0900] "GET /index.html HTTP/1.1" 200 512 "-" "Dummy-UserAgent/1.0" "-"
192.0.2.10 - - [2020-05-16T12:06:06+0900] "GET /test/health_check HTTP/1.1" 200 25 "-" "ELB-HealthChecker/2.0" "-"
.....

aws cli (aws logs filter-log-events) ではどう？

aws cliでももちろん抽出できますが、除外のパターンはちょっとうまく試せず....
JSONで受けてからjqやgrepでフィルタするといいのかもしれません。

# aws logsだと結果はjsonなので、jqで整形
aws logs filter-log-events --log-group-name /TestLogGroup --filter-pattern "ELB" | jq '.events[] | .message'

.....

"192.0.2.10 - - [2020-05-16T12:06:35+0900] \"GET /test/health_check HTTP/1.1\" 200 25 \"-\" \"ELB-HealthChecker/2.0\" \"-\""
"192.0.2.10 - - [2020-05-16T12:06:41+0900] \"GET /test/health_check HTTP/1.1\" 200 25 \"-\" \"ELB-HealthChecker/2.0\" \"-\""
"192.0.2.10 - - [2020-05-16T12:06:46+0900] \"GET /test/health_check HTTP/1.1\" 200 25 \"-\" \"ELB-HealthChecker/2.0\" \"-\""

そもそも書き出さないようにするには？

エンドポイントとしての機能は利用したいけど、そもそもログは書かなくてもいいのでは？というのもあると思います。
こんなやり方で対応できます。ほかにもいろいろあると思うので、今後試しつつ調整したいと思います。

NginxやApacheといったWebサーバ側では、カスタムログの設定で nolog を指定してみる
Railsでhealth check用のエンドポイントを持っている場合は、そのhealth checkのアクションに対してはログを出力しないように設定してみる
- https://github.com/roidrage/lograge (gemのlogrageを追加してignore設定するとか)

以上、ちょっとしたログのメモでした。