概要

CloudWatch Logsのログ取得で、AWS上にログが存在しているにもかかわらず空の情報が返ってくることがあり、その理由を調べた結果そういった仕様であったという話。

ログがあっても空が返ってくることがある

CloudWatch Logsの特定のログストリーム内の、指定期間内のログを取得する処理を、boto3を使ってPythonで作ったものがある。

ある日、ログストリーム内に対象のログがあるのに取得されないということがあった。

いろいろ調査していると、利用しているAPI ( get_log_events ) のドキュメントで以下の説明を見つけた。

This operation can return empty results while there are more log events available through the token.
引用 : https://boto3.amazonaws.com/v1/documentation/api/latest/reference/services/logs.html#CloudWatchLogs.Client.get_log_events

日本語訳

この操作は、トークンを介して利用可能なログイベントがさらにある間、空の結果を返す可能性があります。

この言葉の通り、ログが存在していたとしても (おそらく一時的に) 空の結果を返すこともあるということらしい。

その上で今の実装を見ると、以下のようになっていた。

is_finished = False
next_token = None
log_events = []
while not is_finished:
    args = {
        "logGroupName": log_group_name,
        "logStreamName": log_stream_name,
        "startFromHead": True,
        "limit": limit
    }
    if next_token is not None:
        args["nextToken"] = next_token
    else:
        start_timestamp = datetime_to_millisec_timestamp(start_time)
        end_timestamp = datetime_to_millisec_timestamp(end_time)
        args["startTime"] = start_timestamp
        args["endTime"] = end_timestamp

    response = client.get_log_events(**args)

    if "events" not in response or len(response["events"]) == 0:
        break

    for log_event in response["events"]:
        log_events.append(log_event)

    if "nextForwardToken" not in response:
        is_finished = True
    else:
        next_token = response["nextForwardToken"]

レスポンスに含まれるトークンを利用してページングすることで、条件に該当するログの全件を取得することができる。上記では、そのループ処理の中でで「eventsが空の時」をページの終了と判定してにbreakをしていた。

前述の通り、ログが存在していたとしても空が返ることがあるため、これはログ取得のページングの終了判定の仕方として正しくない。この影響で、ログストリーム内に対象のログがあるのに取得されないという事象が発生したと推測した。

また、ログイベントを取得するAPIとして、get_log_eventsの他に filter_log_eventsがあるが、これも空が返ってくることがある仕様となっている。
https://boto3.amazonaws.com/v1/documentation/api/latest/reference/services/logs.html#CloudWatchLogs.Client.filter_log_events

正しい実装方法

おそらくこのログ自体が結果整合性となっているための仕様であると考えられるが、本当にログが存在しないのか or 今回のようにログが存在するけど取得できなかったのどっちなのか判定をしたい。そのための方法はちゃんと用意されている。

get_log_eventsの場合

レスポンスに含まれるトークン nextForwardToken (遡る場合は nextBackwardToken) で判定する。このトークンが連続して同じ値の時、ページングは終了となる。

If you have reached the end of the stream, it returns the same token you passed in.
引用 : https://boto3.amazonaws.com/v1/documentation/api/latest/reference/services/logs.html#CloudWatchLogs.Client.get_log_events

これをもとに実装し直すと、以下のようになる。

is_finished = False
next_token = None
log_events = []
while not is_finished:
    args = {
        "logGroupName": log_group_name,
        "logStreamName": log_stream_name,
        "startFromHead": True,
        "limit": limit
    }
    if next_token is not None:
        args["nextToken"] = next_token
    else:
        start_timestamp = datetime_to_millisec_timestamp(start_time)
        end_timestamp = datetime_to_millisec_timestamp(end_time)
        args["startTime"] = start_timestamp
        args["endTime"] = end_timestamp

    response = client.get_log_events(**args)

    for log_event in response["events"]:
        log_events.append(log_event)

    if "nextForwardToken" not in response:
        is_finished = True
    elif next_token is not None and response["nextForwardToken"] == next_token:
        is_finished = True
    else:
        next_token = response["nextForwardToken"]

filter_log_eventsの場合

レスポンスに含まれるトークン nextTokenで判定する。この nextTokenが含まれない時、ページングは終了となる。

If the results include a token, then there are more log events available, and you can get additional results by specifying the token in a subsequent call.
引用 : https://boto3.amazonaws.com/v1/documentation/api/latest/reference/services/logs.html#CloudWatchLogs.Client.filter_log_events

これをもとに実装すると、以下のようになる。

is_finished = False
next_token = None
log_events_per_stream = {}
while not is_finished:
    args = {
        "logGroupName": log_group_name,
        "limit": limit
    }
    if next_token is not None:
        args["nextToken"] = next_token
    else:
        start_timestamp = datetime_to_millisec_timestamp(start_time)
        end_timestamp = datetime_to_millisec_timestamp(end_time)
        args["startTime"] = start_timestamp
        args["endTime"] = end_timestamp

    response = client.filter_log_events(**args)

    for log_event in response["events"]:
        message = log_event["message"]
        log_stream_name = log_event["logStreamName"]

        if log_stream_name not in log_events_per_stream:
            log_events_per_stream[log_stream_name] = []
        log_events_per_stream[log_stream_name].append(log_event)

    if "nextToken" not in response:
        is_finished = True
    else:
        next_token = response["nextToken"]

動作確認

空が返ってくる条件は不明で偶発的に起こるもののようなので、再現は出来なさそう。

まとめ

結論としては、ちゃんとドキュメントを読んでいればわかったことであった。
このように検証では見つけるのが難しい条件もあるため、使う際はしっかり読もうということを改めて感じさせられた。

元記事はこちら

https://qiita.com/mmclsntr/items/09ebfa3a6c717923ead4
著者:@mmclsntr


アイレットなら、AWS で稼働するサーバーを対象とした監視・運用・保守における煩わしい作業をすべて一括して対応し、経験豊富なプロフェッショナルが最適なシステム環境を実現いたします。AWS プレミアコンサルティングパートナーであるアイレットに、ぜひお任せください。

AWS 運用・保守サービスページ:
https://cloudpack.jp/service/aws/maintenance.html

その他のサービスについてのお問合せ、お見積り依頼は下記フォームよりお気軽にご相談ください。
https://cloudpack.jp/contact/form/