CloudWatchLogs Insightsで色々集計してみる

CloudWatchLogsにログを流してInsightsでクエリ書いて集計してみた

なお、本記事はクエリのメモがメインなので実行結果まで残っていないものもありあまり参考になるかはわからない

構文について

CloudWatch Logs Insights クエリ構文 - Amazon CloudWatch Logs

docs.aws.amazon.com

料金について

料金 - Amazon CloudWatch | AWS

aws.amazon.com

クエリの実例

nginxのアクセスログから400系のコードごとの件数を取得する

fields @timestamp, @message
| sort @timestamp desc
| parse @message '* - - [*] "* * *" * * "*" "*" "*" "*" "*"' as host, ts, method, path, http, code, size, referer, ua, restime, forwarded, schema
| fields @host,@ts,@method,@path,@code,@referer,@size,@restime
| filter code like /40*/
| stats count(host) by code

nginxのログをパースしてよしなにやるやつ

parseのところで@messageの内容を定義している

正規表現でいう後方参照的なのを*で置き換えるようになっている

nginxのログ形式によるが基本的には↑みたいな感じでOK

実際のログの形式を見ながら定義していく

これやるなら最初からjsonにしておけば…感がでてくる

Railsのログからルーティングエラーのログをフィルタリングしてパスごとの件数を取得する

fields @timestamp,@message
| filter @message like /FATAL/
| parse '*, [* *] * -- : *' as key,ts,hash,level,reason
| filter reason like /.*No route matches.*/
| fields @reason
| parse '"*"' as path
| stats count() by path

RailsのログからFATAL or ERRORのログを抜き出しprefixごとにカウントする

fields @timestamp,@message
| filter @message like /FATAL/ or @message like /ERROR/
| parse '*, [* *] * -- : * *:\n*' as key,ts,hash,level,reason,detail,stacktrace
| display reason,detail,stacktrace
| stats count() as c by reason
| sort c desc

こちらはCloudWatchLogsに流す段階で複数行のログをひと塊と定義できている前提

stacktraceに実際のスタックトレースのテキストが入ってくる

RailsログからERRORまたはFATALの日ごとカウントを計算し時系列で表示できるようにする

fields @timestamp,@message
| filter @message like /FATAL/ or @message like /ERROR/
| stats count() by bin(1d)

独自ログ形式でパースする

次のようなログ形式

E, [2021-05-28T04:30:28.114352 #11836] ERROR -- : (Job{hoge_job} | Hoge::Fuga | [1398617]) failed: #<TypeError: no implicit conversion of nil into String>

こんな感じ

fields @timestamp,@message
| filter @message like /FATAL/ or @message like /ERROR/
| parse '*, [* *] * -- : * [*]*' as key,ts,hash,level,reason,resource_id,detail
| display @message,reason,resource_id,detail
| stats count() as c by reason
| sort c desc

グラフ化

出力の形式次第だがグラフ化もできる

グラフ化したものはdashboardにも追加できるので他の指標などをcloudwatchのdashboardでモニタリングしているのであれば追加しておくと体験は良いかも

cliで試してみる

せっかくなのでCLIでも試してみる

CLIだと aws logs start-query aws logs get-query-results で取得する

JobIDを発行してそのIDをもとに結果を取得する

処理が完了していない段階でもファイルは取得できるので（statusで確認できる）集計が終わったか確認する必要がある点は注意

結果表示用にlimit 3を入れている

$ aws logs start-query --log-group-name '/hoge/production/rails' --start-time $(date -d "last monday 1 week ago" +"%s") --end-time $(date -d "last monday 1 seconds ago" +"%s") --query-string 'fields @timestamp, @message
| sort @timestamp desc
| limit 3' 
{
    "queryId": "3e20c6ca-72b5-4140-80ae-6e462c0d72b0"
}

中身

$ aws logs get-query-results --query-id 3e20c6ca-72b5-4140-80ae-6e462c0d72b0
{
    "results": [
        [
            {
                "field": "@timestamp",
                "value": "2021-03-07 14:59:55.716"
            },
            {
                "field": "@message",
                "value": "I, [2021-03-07T23:59:55.639612 #32626]  INFO -- : Started GET \"/healthcheck\" for 127.0.0.1 at 2021-03-07 23:59:55 +0900"
            },
            {
                "field": "@ptr",
                "value": "CmEKKAokMDQ0NTk1NDEwNTQ2Oi9oYW5kcy9wcm9kdWN0aW9uL3JhaWxzEAISNRoYAgYCnkBCAAAAAFQ5J8IABgROnVAAAAQiIAEororH6YAvMKOLz+mALzgKQPwKSK0QUNoMEAcYAQ=="
            }
        ],
        [
            {
                "field": "@timestamp",
                "value": "2021-03-07 14:59:55.716"
            },
            {
                "field": "@message",
                "value": "I, [2021-03-07T23:59:55.641227 #32626]  INFO -- : Processing by HealthcheckController#index as HTML"
            },
            {
                "field": "@ptr",
                "value": "CmEKKAokMDQ0NTk1NDEwNTQ2Oi9oYW5kcy9wcm9kdWN0aW9uL3JhaWxzEAISNRoYAgYCnkBCAAAAAFQ5J8IABgROnVAAAAQiIAEororH6YAvMKOLz+mALzgKQPwKSK0QUNoMEAgYAQ=="
            }
        ],
        [
            {
                "field": "@timestamp",
                "value": "2021-03-07 14:59:55.680"
            },
            {
                "field": "@message",
                "value": "I, [2021-03-07T23:59:55.637438 #29063]  INFO -- : Started GET \"/healthcheck\" for 127.0.0.1 at 2021-03-07 23:59:55 +0900"
            },
            {
                "field": "@ptr",
                "value": "CmEKKAokMDQ0NTk1NDEwNTQ2Oi9oYW5kcy9wcm9kdWN0aW9uL3JhaWxzEAUSNRoYAgX7uqTEAAAABQ9Fq/EABgROnzAAAABCIAEoj5XI6YAvMJO6z+mALzhjQMN6SJcpUMAlEFoYAQ=="
            }
        ]
    ],
    "statistics": {
        "recordsMatched": 4883260.0,
        "recordsScanned": 4883334.0,
        "bytesScanned": 1022919173.0
    },
    "status": "Complete"
}

@ptrはLogRecordPointerというもの

GetLogRecord - Amazon CloudWatch Logs

docs.aws.amazon.com

statusには集計中の場合はRunningと出ているのでCompleteになるまで再取得しないと正しい集計結果を取得したことにならない

これはGUIだとリアルタイムでグラフや出力が変動するのでわかりやすいがCLIだと見落としてしまいそう

実際に適当に何かクエリを投げてみる

先週分エラーの推移を出力する

 aws logs start-query --log-group-name '/hoge/production/rails' --start-time $(date -d "last monday 1 week ago" +"%s") --end-time $(date -d "last monday 1 seconds ago" +"%s") --query-string "fields @timestamp,@message | filter @message like /FATAL/ or @message like /ERROR/ | stats count() by bin(1d)"

完了した結果をファイルに落としておく

集計する

results.json

{
    "results": [
        [
            {
                "field": "bin(1d)",
                "value": "2021-03-07 00:00:00.000"
            },
            {
                "field": "count()",
                "value": "48"
            }
        ],
        [
            {
                "field": "bin(1d)",
                "value": "2021-03-06 00:00:00.000"
            },
            {
                "field": "count()",
                "value": "92"
            }
        ],
.....
.....

集計する

$ cat results.json | jq '.results|map({key: (.[0].value|split(" ")|.[0]), value: .[1].value})|from_entries'
{
  "2021-03-07": "8",
  "2021-03-06": "2",
  "2021-03-05": "20",
  "2021-03-04": "3",
  "2021-03-03": "5",
  "2021-03-02": "10",
  "2021-03-01": "4",
  "2021-02-28": "7"
}

ぽい感じになった

あとは適当なデータソースに突っ込んで可視化みたいな流れで簡単にログの推移を把握できる