Help us understand the problem. What is going on with this article?

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]

すると、ログに設定した日付を判別して、勝手にローテートされるようになりました。
うまくローテーションがかからなくてログの一部が翌日になったら送れなくなった人はお試しください。

こちらの記事は自社のブログに書いたものの転記になります
https://core-tech.jp/blog/article431/

pugtech1
コアテックに所属して7年目のお局 特技は3秒で寝ること
https://core-tech.jp/blog/employee_id7/
core-tech
100%自社内で月間数千万PVのWebサービスを受託開発する安定&成長企業
https://core-tech.jp/
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Comments
No comments
Sign up for free and join this conversation.
If you already have a Qiita account
Why do not you register as a user and use Qiita more conveniently?
You need to log in to use this function. Qiita can be used more conveniently after logging in.
You seem to be reading articles frequently this month. Qiita can be used more conveniently after logging in.
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
ユーザーは見つかりませんでした