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


やりたいこと

表題の通りです。

なぜ?

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

前提条件

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

やってみる

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

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™ というキャッチコピーがリポジトリに書かれていますが、まさに大助かりです...。

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

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

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

/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のアクションに対してはログを出力しないように設定してみる

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