概要
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"]
動作確認
空が返ってくる条件は不明で偶発的に起こるもののようなので、再現は出来なさそう。
まとめ
結論としては、ちゃんとドキュメントを読んでいればわかったことであった。
このように検証では見つけるのが難しい条件もあるため、使う際はしっかり読もうということを改めて感じさせられた。