CloudWatch Logs Insights クエリを定期的に実行して結果をS3に置く(EventBridge Scheduler, Step Functions, Lambda)

カヤックSREの今です。

SRE連載8月のエントリーになります。

techblog.kayac.com

Amazon CloudWatch Logs Insights(以下Insights)は、CloudWatch Logsのログを期間を指定して検索、集計、簡単な文字列処理を行うことが出来ます。 Webコンソールから手軽に利用することができ、エラーが起きた際のログ調査に日常的に利用しています。

クエリは非同期で実行されますが、Webコンソールからクエリを実行して結果の表示前にページを離れてしまうと、クエリ結果をWebコンソール上で確認することができません。 Webコンソール上の履歴からリクエストIDを取得し、AWS CLIからaws logs get-query-result --query-id=[リクエストID]を実行することで結果をjsonで得ることができます。

今回は自動で日時の集計クエリをInsightsで実行し、結果をAmazon S3に保存する例をご紹介します。

クエリを定期実行するモチベーション

Insightsでは、アプリケーションが出力したログをクエリで検索・集計することによって、例えばアクセスログの調査、DAU(Daily Active User)の集計、課金APIのログのみを抽出などを行うことが出来ます。 Webコンソールからクエリを実行した場合の多くは、そのままWebコンソール上で結果を確認、あるいはCSV等をダウンロードして保存することが多いと思います。頻繁に使う集計クエリを定期実行して結果を保存することで、調査や分析の際に過去全てのログを洗い出す必要が無くなったり、調査や分析に利用したりすることが出来ます。

AWSには以下の仕様があります。

Insightsの最長実行時間は60分
AWS Lambdaの最長実行時間は15分*1

AWS Lambdaでクエリの実行・S3への保存を行うと、Insightsのクエリ実行が完了するのを待っている間にLambdaがタイムアウトしてしまう可能性があります。そこで今回は、AWS Step Functionsを用いてクエリID(Webコンソール上ではリクエストIDと表記される。以下クエリID)を一度の実行の中で保存し、Insigthsの実行完了まで待機する仕組みを作成します。

実装例

作成する(した)リソース

Lambda
- logs-query-exec
Step Functions ステートマシン
EventBridge Scheduler
IAM Role
- Lambda
  - AWSLambdaBasicExecutionRole
  - CloudWatchLogsReadOnlyAccess
- Step Functions
  - lambda:InvokeFunction
- EventBridge Scheduler
  - states:StartExecution

クエリを受け取ったら実行して結果をS3に置くLambdaを作成する(logs-query-exec)

今回はLambdaでInsightsのクエリ実行し、完了後にS3へ結果を保存するツールを作成しました。 https://github.com/ToshihitoKon/logs-query-exec

aws lambda invoke、あるいは関数URLにリクエストでaws logs start-queryのオプションを渡すと実行した結果をS3に保存します。レスポンスにはクエリIDと最後のInsightsのクエリ実行状態が含まれています。 Lambdaからレスポンスが返る時点でクエリが未完了だった場合、クエリIDを与えて実行すると完了するまで待機し、完了したらS3に出力します。

Step Functionsでステートマシンを作る

logs-query-execはLambda上で動作しますが、Lambdaの最大実行時間は前述の通り15分のため、Insightsが15分以上かかるクエリを処理した結果を受け取ることができません。手で叩く場合はクエリIDを見てlogs-query-execを再度実行できますが、今回の目標は定期実行なので自動でクエリIDを保持してLambdaを再度実行する仕組みをStep Functionsで作成します。

作成した状態遷移は以下になります

ステートマシンの定義

{
  "Comment": "A description of my state machine",
  "StartAt": "Lambda Invoke",
  "States": {
    "Lambda Invoke": {
      "Type": "Task",
      "Resource": "arn:aws:states:::lambda:invoke",
      "Parameters": {
        "FunctionName": "arn:aws:lambda:ap-northeast-1:xxxxxxx:function:logs-query-exec",
        "Payload": {
          "body.$": "States.Base64Encode(States.JsonToString($.body))",
          "isBase64Encoded": true
        }
      },
      "Retry": [
        {
          "ErrorEquals": [
            "Lambda.ServiceException",
            "Lambda.AWSLambdaException",
            "Lambda.SdkClientException",
            "Lambda.TooManyRequestsException"
          ],
          "IntervalSeconds": 5,
          "MaxAttempts": 3,
          "BackoffRate": 2,
          "Comment": "retry"
        }
      ],
      "ResultSelector": {
        "body": {
          "query_id.$": "$.Payload.query_id"
        },
        "enable_retry.$": "$.Payload.enable_retry",
        "file_path.$": "$.Payload.file_path"
      },
      "Next": "Choice"
    },
    "Choice": {
      "Type": "Choice",
      "Choices": [
        {
          "Variable": "$.enable_retry",
          "BooleanEquals": true,
          "Next": "Lambda Invoke"
        },
        {
          "Not": {
            "Variable": "$.file_path",
            "StringEquals": ""
          },
          "Next": "Success"
        }
      ],
      "Default": "Fail"
    },
    "Success": {
      "Type": "Succeed"
    },
    "Fail": {
      "Type": "Fail",
      "Error": "ErrorCode",
      "Cause": "Caused By Message"
    }
  }
}

Lambda Invokeでlogs-query-execを実行
Choiceでlogs-query-execの結果からリトライ可能すべきかどうかを判断
- レスポンスに保存したファイルパスが入っていたらSuccess
- ファイルパスが入っておらずリトライ可能であれば、クエリIDをbodyに含めて再度Lambda Invokeを実行
- ファイルパスが入っておらず、リトライも不可能であればFail

EventBridge Schedulerで定期的にStep Functionsを開始する

作成したStep Functionsを立ち上げるのにはEventBridge Schedulerを利用します。 Step Functionsへリクエストを送る際に、ペイロードにlogs-query-execのオプション、つまりはInsightsのクエリ本文を入力します。（logs-query-execの都合上、Base64Encodeしたものを入れています）

異なるInsightsクエリを定期実行したい場合は、EventBridge Scheduler側でクエリを変更したものを用意しておくだけで結果がS3に保存されるようになります。

結果がS3に置かれたらよしなにする

Step Functionsの中で渡される状態の中にS3ファイルパスが含まれているので、ここから更に処理を追加することも出来ます。S3に上がったファイルをSlackへPostするLambdaなんかを置くと観察が捗りそうですね。 jsonで保存されているので、調査や分析の際にAmazon Athenaを使うことも出来るかもしれません。

デモ

実際に15分以上かかるInsightsクエリを作るのは難しいので、デモ用にlogs-query-execのタイムアウトを極端に短くしたものをデプロイして強制的にリトライさせます。今回はデモのためEventBridgeのペイロードにクエリ範囲時間をベタ書きしてあります。クエリIDは実行ごとに変わりますが、結果は同じ物が出力されます。

Lambda Invokeが複数回実行され、最終的にPassにたどり着く様子を見ることが出来ました。

0 (*>△<) % aws s3 ls s3://xxxxx/logs-query-exec/output/8b3e2bb9-a8c7-42c3-8a85-dc2cf9ff6593.json
2023-08-29 23:52:29      17895 8b3e2bb9-a8c7-42c3-8a85-dc2cf9ff6593.json

0 (*>△<) % cat 8b3e2bb9-a8c7-42c3-8a85-dc2cf9ff6593.json | jq '.[]."@message"'
"2023/08/28 10:02:58.870206 webapi.go:364: [info] purge subdomains: duration=1h0m0s, excludes=[], exclude_tags=[keep:true]"
"2023/08/28 10:03:38.614263 mirage.go:144: [info] access counters: {}"
"2023/08/28 10:03:58.877554 webapi.go:364: [info] purge subdomains: duration=1h0m0s, excludes=[], exclude_tags=[keep:true]"
"2023/08/28 10:04:38.613743 mirage.go:144: [info] access counters: {}"
"2023/08/28 10:04:58.899966 webapi.go:364: [info] purge subdomains: duration=1h0m0s, excludes=[], exclude_tags=[keep:true]"
"2023/08/28 10:05:38.614365 mirage.go:144: [info] access counters: {}"
"2023/08/28 10:05:58.815517 webapi.go:364: [info] purge subdomains: duration=1h0m0s, excludes=[], exclude_tags=[keep:true]"
"2023/08/28 10:06:38.614050 mirage.go:144: [info] access counters: {}"
"2023/08/28 10:06:58.819182 webapi.go:364: [info] purge subdomains: duration=1h0m0s, excludes=[], exclude_tags=[keep:true]"
"2023/08/28 10:07:38.614287 mirage.go:144: [info] access counters: {}"
...

S3にファイルがアップロードされ、クエリ結果のjsonの内容も正しく入っていることが確認出来ました。ちなみにこちらはmirage-ecsのログになります。