概要
CloudWatch Logs のサブスクリプションフィルタの実行タイミングを確認してみた話。
サブスクリプションフィルタとは
CloudWach Logs のフィルタは、ログ内の一定の文字列パターンを検知し、他のサービスへ連携する際に利用する。
フィルタの種類としては、メトリクスフィルタとサブスクリプションフィルタがある。
メトリクスフィルタでは、文字列パターンを検知した後、その出現頻度等の CloudWatch メトリクスに変換して記録する。他のサービスと連携を行う場合には、さらにメトリクスを監視する CloudWatch アラームを設定する。
サブスクリプションフィルタでは、文字列パターンを検知した後、検知したログを直接 Kinesis や Lambda に連携する。メトリクスフィルタと比較したサブスクリプションフィルタの特徴は、ログのリアルタイム検知が可能なこと、ログの内容を送信できることである。
サブスクリプションフィルタではリアルタイムでログが連携されるようだったが、複数ログが同時に送信されたりする場合があったので、ちゃんと確認してみた。
内容
結論から
結論から言うと、サブスクリプションフィルタは CloudWatch Logs に対してログが置かれたタイミングで実行される。
何かすごく当たり前のことを言っているような気がするが、重要なのはログが CloudWatch Logs に置かれたタイミングというのは、ログのタイムスタンプとは全く別物だということだ。
ログを CloudWatch Logs に置く場合、PutLogEvents という API が実行される。
PutLogEvents という名前の通り、この API によって複数のログイベントを同時に CloudWatch Logs に書き込むことができる。
つまり、サブスクリプションフィルタでは、タイムスタンプが違うログだとしても、CloudWatch Logs に同時に書き込まれたログは同時に通知される。
ログについての情報は、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-pagerput-log-events 実行時には sequence-token なるものを含めないといけないらしいので、describe-log-streams の結果から sequence-token を取得して使用している。
実行結果
上記のスクリプトを実行して、それぞれ異なるタイムスタンプで3つのログを置いた。
（一番上はコンソールから置いたログ）
Lambda の実行ログを見ると、タイムスタンプの異なる2つのログイベントが同時に通知されていることが分かる。
まとめ
サブスクリプションフィルタは、CloudWatch Logs に対して PutLogEvents されたタイミングで実行される。
複数ログイベントが PutLogEvents によって同時に置かれた場合は、サブスクリプションフィルタからも同時に通知される。
感想
CloudWatch Logs にログが置かれないとサブスクリプションフィルタで検知できないんだから、ログが置かれたタイミングで実行されるってのはよく考えると当たり前な気がする。
でも、最初は PutLogEvents のタイムスタンプとログのタイムスタンプをごっちゃにしていたせいで、サブスクリプションフィルタの実行タイミングがはっきり分かっていなかった。
ドキュメントには、「ログイベントのリアルタイムフィードにアクセス」すると書かれているが、動作を確認してその意味がちゃんと分かった。
これで、この主張も完全に理解した。
リプにあるけど、CloudWatch Logs にログが置かれるのが遅れたとしても対応できる。
そう、サブスクリプションフィルタなら。
参考
