サブスクリプションフィルタの実行タイミング

Study

概要

CloudWatch Logs のサブスクリプションフィルタの実行タイミングを確認してみた話。

サブスクリプションフィルタとは

CloudWach Logs のフィルタは、ログ内の一定の文字列パターンを検知し、他のサービスへ連携する際に利用する
フィルタの種類としては、メトリクスフィルタとサブスクリプションフィルタがある。

メトリクスフィルタでは、文字列パターンを検知した後、その出現頻度等の CloudWatch メトリクスに変換して記録する。他のサービスと連携を行う場合には、さらにメトリクスを監視する CloudWatch アラームを設定する。

サブスクリプションフィルタでは、文字列パターンを検知した後、検知したログを直接 Kinesis や Lambda に連携する。メトリクスフィルタと比較したサブスクリプションフィルタの特徴は、ログのリアルタイム検知が可能なこと、ログの内容を送信できることである。

サブスクリプションフィルタではリアルタイムでログが連携されるようだったが、複数ログが同時に送信されたりする場合があったので、ちゃんと確認してみた。

内容

結論から

結論から言うと、サブスクリプションフィルタは CloudWatch Logs に対してログが置かれたタイミングで実行される

何かすごく当たり前のことを言っているような気がするが、重要なのはログが CloudWatch Logs に置かれたタイミングというのは、ログのタイムスタンプとは全く別物だということだ。

ログを CloudWatch Logs に置く場合、PutLogEvents という API が実行される。
PutLogEvents という名前の通り、この API によって複数のログイベントを同時に CloudWatch Logs に書き込むことができる。

つまり、サブスクリプションフィルタでは、タイムスタンプが違うログだとしても、CloudWatch Logs に同時に書き込まれたログは同時に通知される

PutLogEvents - Amazon CloudWatch Logs
Uploads a batch of log events to the specified log stream.

ログについての情報は、InputLogEvent としてログの内容(message)とログのタイムスタンプ(timestamp)が渡されているが、このタイムスタンプはサブスクリプションフィルタの実行タイミングとは無関係である。

触ってみた記録

せっかくなので触った記録を。

CloudWatch Logs にサブスクリプションフィルタを設定し、Lambda で通知を受け取って通知内容を出力する、といった感じ。

準備

基本的にはコンソールから GUI でポチポチして作成。
サブスクリプションフィルタでは「ERROR」という文字列を検知するように設定した。

↓ 使用した Lambda コード

import base64
import gzip
import json
from logging import getLogger, DEBUG

logger = getLogger(__name__)
logger.setLevel(DEBUG)



def lambda_handler(event, context):
    
    event_byte = base64.b64decode(event['awslogs']['data'])
    event_str = gzip.decompress(event_byte).decode('utf-8')
    
    event_dict = json.loads(event_str)
    
    logger.debug(json.dumps(event_dict))
    
    for log_event in event_dict['logEvents']:
    
        logger.debug(log_event['message'])
    
    return { 'statusCode': 200 }

上述したように複数のログイベントが送信される可能性があるので、ログイベント分 for ループを実行してログメッセージを出力している。
Lambda から SNS 通知するような場合、for ループしないと通知漏れが発生するので注意。

ログイベントの作成について、コンソールからだと「意外と面倒」&「同時に複数ログイベント作成ができない」ので、CLI を使用した。

↓ Put するログイベント(log-events.json)

[
  {
    "timestamp": 1685765838736,
    "message": "1 ERROR"
  },
  {
    "timestamp": 1685765838883,
    "message": "2 WARN"
  },
  {
    "timestamp": 1685765838924,
    "message": "3 ERROR"
  }
]

↓ PutLogEvents 実行のための bash スクリプト

#!/bin/bash

log_group_name="[ロググループ名]"
log_stream_name="[ログストリーム名]"

log_streams=$(aws logs describe-log-streams \
    --log-group-name ${log_group_name} \
    --log-stream-name ${log_stream_name} \
    --no-cli-pager)

log_stream_list=(${log_streams})
sequence_token=${log_stream_list[-1]}

aws logs put-log-events \
    --log-group-name ${log_group_name} \
    --log-stream-name ${log_stream_name} \
    --log-events file://log-events.json \
    --sequence-token ${sequence_token} \
    --no-cli-pager

put-log-events 実行時には sequence-token なるものを含めないといけないらしいので、describe-log-streams の結果から sequence-token を取得して使用している。

実行結果

上記のスクリプトを実行して、それぞれ異なるタイムスタンプで3つのログを置いた。
(一番上はコンソールから置いたログ)

Lambda の実行ログを見ると、タイムスタンプの異なる2つのログイベントが同時に通知されていることが分かる。

まとめ

サブスクリプションフィルタは、CloudWatch Logs に対して PutLogEvents されたタイミングで実行される
複数ログイベントが PutLogEvents によって同時に置かれた場合は、サブスクリプションフィルタからも同時に通知される。

感想

CloudWatch Logs にログが置かれないとサブスクリプションフィルタで検知できないんだから、ログが置かれたタイミングで実行されるってのはよく考えると当たり前な気がする。
でも、最初は PutLogEvents のタイムスタンプとログのタイムスタンプをごっちゃにしていたせいで、サブスクリプションフィルタの実行タイミングがはっきり分かっていなかった。

ドキュメントには、「ログイベントのリアルタイムフィードにアクセス」すると書かれているが、動作を確認してその意味がちゃんと分かった。

これで、この主張も完全に理解した。

リプにあるけど、CloudWatch Logs にログが置かれるのが遅れたとしても対応できる
そう、サブスクリプションフィルタなら

参考

サブスクリプションを使用したログデータのリアルタイム処理 - Amazon CloudWatch Logs
CloudWatch Logs サブスクリプションを使用して、ログデータをリアルタイムで処理します。
CloudWatch Logs を文字列検知してログ内容をメールを送信してみた サブスクリプションフィルター版 | DevelopersIO
CloudWatch Logs のログから特定文字列をマッチさせ SNS から通知する方法を紹介します。
CloudWatch Logs で Lambda を使用する - AWS Lambda
Amazon CloudWatch Logs で Lambda 関数をトリガーします。
describe-log-streams — AWS CLI 2.11.25 Command Reference
put-log-events — AWS CLI 2.11.25 Command Reference
文字列をCloudWatchLogsにPUTしてみた | DevelopersIO
はじめに こんにちは。 くコ:彡がトレードマークの阿部です。 CloudWatch Logsを使うと、OSやアプリケーションログをAWSに転送する事が出来ます。 Linux、Windowsを問わずに利用可能です。 Clo …
タイトルとURLをコピーしました