はじめに

CloudWatch Logsへのログ転送を行う機会がありましたが、タイムスタンプのエラーでハマりました。。。

目的

元々の目的は、以下の内容です。

EC2のログをCloudWatch Logsに転送させる
- EC2のログは、ECS（on EC2）のログをMountしたもの
ログイベントに表示されるタイムスタンプは、ログのタイムスタンプと一致させる

実施内容

CloudWatch Logsエージェントのインストール

sudo yum install -y awslogs

CloudWatch Logsエージェントの設定

/etc/awslogs/awscli.conf の region を修正

[plugins]
cwlogs = cwlogs
[default]
region = ap-northeast-1

/etc/awslogs/awslogs.conf に転送したいログを指定
- datetime_format をログのタイムスタンプとあわせることで、ログイベントに表示されるタイムスタンプとログのタイムスタンプと一致させることができますので、フォーマットを指定しました
  - 実際のログには、2021-03-18 21:13:51.059 のような形式で出力されています。
- time_zone は、LOCAL か UTCを指定します。コンテナはJSTで、ログのタイムスタンプもJSTなので、LOCALを指定しました。

[debug.log]
log_group_name = /var/log/app/debug.log
datetime_format = %Y-%m-%d %H:%M:%S.%f
time_zone = LOCAL
file = /var/log/app/debug.log
buffer_duration = 5000
log_stream_name = {instance_id}.log
initial_position = start_of_file

CloudWatch Logsエージェントの開始

sudo systemctl start awslogsd

これで、CloudWatch Logsへ転送が開始されるはずでしたが、されませんでした。

エラー出力

CloudWatch Logsのログは、/var/log/awslogs.log に出力されます（初期値）。
ログには、以下のWARNINGが出力、CloudWatch Logsへの出力がスキップされていました。

2021-03-21 03:02:03,624 - cwlogs.push.batch - WARNING - 20493 - Thread-4 - Skip event: {'timestamp': 1616328122772, 'start_position': 11528702L, 'end_position': 11528949L}, reason: timestamp is more than 2 hours in future.
2021-03-21 03:02:03,624 - cwlogs.push.batch - WARNING - 20493 - Thread-4 - Skip event: {'timestamp': 1616328122773, 'start_position': 11528949L, 'end_position': 11529168L}, reason: timestamp is more than 2 hours in future.

トラブルシューティング

を確認すると、

直前のイベント時間に戻る: {'timestamp': 1492395793000, 'start_position': 17280L, 'end_position': 17389L}, previousEventTime: 1492395793000, 理由: メッセージからタイムスタンプを解析できませんでした。 – ログイベントがタイムスタンプで開始されることを確認します。/etc/awslogs/awslogs.conf で指定された datetime_format がログイベントのタイムスタンプ形式と一致するかどうかを確認します。必要に応じて、タイムスタンプ形式と一致するように datetime_format を変更します。

とありましたので、datetime_formatを疑いました。
若干、引っかかっていたところがあり、ログ上は、ミリ秒の出力なのに、フォーマットは、マイクロ秒で指定していたので、正しく解析できていないのでは？と思いました。

# ----------------------------------------------------------------------------------------------------------------------
#  %f           Microsecond as a decimal number, zero-padded on the left.                               000000, 000001, ..., 999999
# ----------------------------------------------------------------------------------------------------------------------

ログ上は、3桁。フォーマットは、6桁を想定しているっぽいです。ただ、フォーマットには、ミリ秒の指定はない。。。
エラーログも、 timestamp is more than 2 hours in future. なので、タイムスタンプの解析自体はできている？？？

原因

Timezone不一致で、タイムスタンプの解析が出来ていなかったようです。

EC2(UTC)
ECS(JST)

エラーログのタイムスタンプを確認すると JST + 9:00 となっていました。タイムスタンプのフォーマットから、Timezoneの判断が出来ず、time_zone = LOCAL と指定していたことから、ログのタイムスタンプ+9:00で出力しようとしたため、スキップとなっていたようです。

　※ フォーマットの桁数は、あくまで例で、確かに**zero-padded on the left.**なら、上位3桁はミリ秒ですね。。。

対処

対処としては、

ログの出力フォーマットをTimezoneがわかる形式に修正する
Timezoneを変更する（EC2とECSであわせる）

の何れかと思います。

今回は、EC2のTimezoneを変更することで、スキップを回避、タイムスタンプを一致させることが出来ました。
（既にECSでアプリが動いていたこともあり、アプリに影響を与えたくなかったです）

終わりに

普段、Timezoneの表現まで意識していませんでした。要件に影響しないのであれば、入れておいた方が無難っぽいですね。