信頼はずっと、挑戦はもっと。

お問い合わせ
TEL:03-3496-3888

BLOG コアテックの社員ブログ (毎週月曜~金曜更新中)

2019

7

10月

CloudWatch Logsエージェントがローテートさせるとtimestamp is more than 2 hours in future.で止まってしまう件について

テクログ

こんにちわ。パグです。


本日はCloudWatch Logsエージェントのログがtimestamp is more than 2 hours in futureで

止まってしまう件について書きます。

現在の環境はFuelPHPで、主にFuelPHPのローテートログをCloudWatchエージェントで

PUSHさせたいって内容になっています。

が、恐らく他の環境のログの場合で起きた事象もこれに近しいのではないかと思います。


CloudWatchLogsエージェントは導入済みで、ローテート時にうまく動かない人向けなので、

そもそもCloudWatchLogsにログが反映されていない場合は別の要因によるのではないかと思います。


[/server/fuelphp/logs]
datetime_format = %Y-%m-%d %H:%M:%S
file = /path/to/fuel/app/logs/20*/*/*
buffer_duration = 5000
log_stream_name = {instance_id}
initial_position = start_of_file
log_group_name = /server/fuelphp/logs



他にマルチラインの設定などが必要かと思いますが、簡単に書くとこんな感じに設定。

CloudWatch側では、log_group_nameで検索ができるようになりますが、翌日

「 timestamp is more than 2 hours in future.」とエラーが出ており

PUSHイベントが動いていません。色々調べていて、皆大好きStackOverflowを見て見ると、以下のような記事が。


https://stackoverflow.com/questions/40604940/cloudwatch-logs-acting-weird

https://forums.aws.amazon.com/thread.jspa?threadID=243092


この記事の人に激しく同意

>Yes I'm experiencing the issue too. Is there a way to reset the state file without doing this?

うん。私もそう思うわ。それやらないでResetしたいんだよぉぉぉぉ。


はい。じゃあ。本題です。

awslogsのPUTイベントが失敗する原因は以下です。

PutLogEvents オペレーションの制約に従って、次の問題によりログイベントまたはバッチがスキップされる場合があります。

以下本家のマニュアルから抜粋

https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/WhatIsCloudWatchLogs.html


注記

1.データがスキップされた場合、CloudWatch Logs エージェントはログに警告を書き込みます。
2.ログイベントのサイズが 256 KB を超過した場合、ログイベントは完全にスキップされます。
3.ログイベントのタイムスタンプが 2 時間以上未来の場合、ログイベントはスキップされます。
4.ログイベントのタイムスタンプが 14 日以上過去の場合、ログイベントはスキップされます。
5.ログイベントがロググループの保持期間よりも古い場合、バッチはすべてスキップされます。
単一の PutLogEvents リクエストでログイベントのバッチが 24 時間実行されている場合、PutLogEvents オペレーションは失敗します。


上記の3がこの「 timestamp is more than 2 hours in future.」というエラーにあたります。

タイムスタンプが実行時間より2時間以上未来日になっているので、スキップしますとのことで、最初は

UTCと日本時間のズレのせいかと考えたのですが、どうもズレている時刻が異なります。


実行タイムスタンプの調べ方はStackOverflowに書いてある通りで「/var/lib/awslogs/agent-state」を

sqlite3で検索(JSON形式で保存されているので実行された体の時刻を調べます)

調べるストリームIDは/var/log/awslogs.logに出ています。

2019-09-28 06:01:02,041 - cwlogs.push.stream - INFO - 12879 - Thread-1 - Removing dead reader [77cbf636732d4f124469c8ccb0f71abe, /logs/2019/09/27.php]
2019-09-28 06:01:02,041 - cwlogs.push.stream - INFO - 12879 - Thread-1 - Removing dead publisher [77cbf636732d4f124469c8ccb0f71abe, /logs/2019/*/*.php]
2019-09-28 06:01:02,044 - cwlogs.push.stream - INFO - 12879 - Thread-1 - Starting publisher for [77cbf636732d4f124469c8ccb0f71abe, /logs/2019/09/28.php]
2019-09-28 06:01:02,044 - cwlogs.push.stream - INFO - 12879 - Thread-1 - Starting reader for [77cbf636732d4f124469c8ccb0f71abe, /logs/2019/09/28.php]

上記の77cbf636732d4f124469c8ccb0f71abeです。

(PATHはサイトの詳細が記載してあるので少し削りました)これを検索します。


[root@server]# sqlite3 /var/lib/awslogs/agent-state
SQLite version 3.7.17 2013-05-20 00:56:22
Enter ".help" for instructions
Enter SQL statements terminated with a ";"
sqlite> select * from push_state where k="8deaef1856dda2abe912ceedc4180f53";

上記のkの部分にストリームIDを入れると、JSONからPUSHした時にイベントが出てきます。


8deaef1856dda2abe912ceedc4180f53|{"start_position": 248, "source_id": "8deaef1856dda2abe912ceedc4180f53", "first_timestamp": 1570412666000, "first_timestamp_status": 1, "sequence_token": "49599891918873079124975725871068904036184047788058782002", "batch_timestamp": 1570412666866, 
"end_position": 369}|2019-10-06T21:00:13|2019-10-07T01:44:32


このFirstTimestampとbatchtimestampが明らかに前日になっています。

前日になっていますが、9時間ズレとかではありません。なのでUTCの問題ではありません。

なんでかなーと調べていくと、書き込まれない時に、ローテートされた後のログストリームIDがずっと変わらないではありませんか。


2019-09-28 06:00:58,041 - cwlogs.push.reader - INFO - 12879 - Thread-1346 - Reader is leaving as requested...
2019-09-28 06:01:02,041 - cwlogs.push.stream - INFO - 12879 - Thread-1 - Removing dead reader [77cbf636732d4f124469c8ccb0f71abe, /logs/2019/09/27.php]
2019-09-28 06:01:02,041 - cwlogs.push.stream - INFO - 12879 - Thread-1 - Removing dead publisher [77cbf636732d4f124469c8ccb0f71abe, /logs/2019/*/*.php]
2019-09-28 06:01:02,044 - cwlogs.push.stream - INFO - 12879 - Thread-1 - Starting publisher for [77cbf636732d4f124469c8ccb0f71abe, /logs/2019/09/28.php]
2019-09-28 06:01:02,044 - cwlogs.push.stream - INFO - 12879 - Thread-1 - Starting reader for [77cbf636732d4f124469c8ccb0f71abe, /logs/2019/09/28.php]
2019-09-28 06:01:02,045 - cwlogs.push.reader - INFO - 12879 - Thread-1348 - Replay events end at 384.
2019-09-28 06:01:02,045 - cwlogs.push.reader - INFO - 12879 - Thread-1348 - Start reading file from 74.
2019-09-28 06:01:02,045 - cwlogs.push.batch - WARNING - 12879 - Thread-1348 - Skip event: {'timestamp': 1569618001000, 'start_position': 74L, 'end_position': 153L}, reason: timestamp is more than 2 hours in future.
2019-09-28 06:09:30,216 - cwlogs.push.batch - WARNING - 12879 - Thread-1348 - Skip event: {'timestamp': 1569618569000, 'start_position': 153L, 'end_position': 229L}, reason: timestamp is more than 2 hours in future.


ダメだった時のログはこんな感じで。Removing dead publisherしてるのにStarting publisherのストリームIDが

変わらない。77cbf636732d4f124469c8ccb0f71abeこの場合、翌日になっているのにずっとタイムスタンプ上9月27日の朝6時とかに

なっているので、9月28日のPUSHとならずに、スキップされてしまいます。


原因は、FuelPHPのログって、一番上位に

<?php defined('COREPATH') or exit('No direct script access allowed'); ?>

こんな感じの固定文言が出ているんですけど、こいつが前日とまったく同じなものだから、

Startを前日のログから検索してしまって、日付がリセットされないーって内容でした。

なので、FuelPHPはCoreの LogsClassをOverwriteして

2019-10-01 08:26:02<?php defined('COREPATH') or exit('No direct script access allowed'); ?>

タイムスタンプを突っ込んでやりました。


2019-10-07 06:00:08,256 - cwlogs.push.stream - INFO - 14088 - Thread-1 - Removing dead reader [729a61c49dafeeb9472f9bc030510546, /logs/2019/10/06.php]
2019-10-07 06:00:08,261 - cwlogs.push.stream - INFO - 14088 - Thread-1 - Starting reader for [8deaef1856dda2abe912ceedc4180f53, /logs/2019/10/07.php]

すると、ログに設定した日付を判別して、勝手にローテートされるようになりました。

うまくローテーションがかからなくてログの一部が翌日になったら送れなくなった人はお試しください。


(Sitemapって、エラーじゃないやんけとか、いわない。)

ではでは〜。

この記事を書いた人

画像:投稿者アイコン

パグ

所 属:
WEBインテグレーション事業部
出身地:
田舎
仕事内容:
システム開発

RELATED ARTICLE

関連記事

記事一覧へ