[Datadog]Date Remapperで扱う時刻

はじめに

こんにちは、なじむです。今回はDatadogの設定で「あれ？」と思ったところがあったので記事を書きたいと思います。
皆さん、DatadogでElasticsearchのログ監視は行っていますか？もし行っていたら「あれ？」と思うことはありませんでしたか？
私は何故かログを出力した時刻とDatadogのLogsから見れる時刻が9時間ずれてしまう（実際にログを出力してからDatadog上で見れるのが9時間後になる）事象に遭遇しました。そう、UTCとJSTの時刻差です。今回は何故そのようなことになったのか記事を書いていきたいと思います。

前提

今回の事象は以下の状況で発生します。

• ElasticseatchをインストールしているサーバのTime Zone設定が「Asia/Tokyo (UTC+09:00)」になっている
• Datadog上のTime Zone設定が「Asia/Tokyo (UTC+09:00)」になっている
  

やってみる

動作確認

具体的にどのような動作なのか確認してみます。
/var/log/elasticsearch/elasticsearch.logにログを出力し、Datadog上でどのように見えるのか確認します。この項目はテストなのでログの出力を現在時刻より9時間前の時刻として出力します。
結果として、時刻が以下になっていることが確認できるかと思います。
・ログの日付：2020/4/26/ 11:08:29.000
・Datadog上の時間：2020/4/26/ 20:08:29.000

ログの出力

# echo "[\`date -d '-9 hours' "+%FT%T,000"\`][INFO ][foo.bar] This is a test message" >> /var/log/elasticsearch/elasticsearch.log
# tail -n 1 /var/log/elasticsearch/elasticsearch.log
[2020-04-26T11:08:29,000][INFO ][foo.bar] This is a test message
#

Datadog上で確認

原因

上述のように実際のログの時刻とDatadog上のログが9時間ズレます。その場合、ログを検知してから通知するまで9時間のラグが発生することになるため監視にはなりません。それが発生する原因はDatadog上のPipelineで実施しているDate Remapperの設定によるものです。Elaticsearchの場合は以下の様になっています。

ざっくりとした流れは以下の様になっています。詳細はDatadogのプロセッサーを参照ください。
①Grok Parser：ログを分割し、ATTRIBUTESに格納 ※今回はtimestamp, levelの2つ
②Date Remapper：①で分割したtimestampをDatadog上で表示する時刻に変換
③Status Remapper：①で分割したlevelをDatadog上のステータスに変換

先ほどのDatadogのページのログ日付リマッパーの項には以下の表示があります。

認識される日付の形式は、ISO8601、UNIX (ミリ秒エポック形式)、および RFC3164 です。

つまり、②Date Remapperを実行した際、読み込む時刻がJSTでもDatadogはUTCとして認識するため、DatadogのtimezoneがAsia/Tokyoだった場合は9時間を追加されてしまうという流れになっていました。

対応策

対応策は2種類あるかなと思います。

1. Date Remapperを無効にする
2. 9時間引いた値をDate Remapperにかける

Date Remapperを無効にする

こちらはとてもお手軽です。先ほどのPipeline中のDateRemapperを無効に(または削除)すれば完了です。
Datadogのインテグレーションから作成されたデフォルトのルールは編集ができないのでクローンしてから修正します。その際、元のルールは無効にしておきます。 ※無効になるのがデフォルトの動作です。

どのように変化したのか確認します。Date Remapperを無効にしたので、現在時刻でログを出力します。そうすると以下の様に微妙にずれました。
・ログの日付：2020/4/26/ 20:50:28.000
・Datadog上の時間：2020/4/26/ 20:50:28.653

ログの出力

# echo "[`date "+%FT%T,000"`][INFO ][foo.bar] This is a test message" >> /var/log/elasticsearch/elasticsearch.log
# tail -n 1 /var/log/elasticsearch/elasticsearch.log
[2020-04-26T20:50:28,000][INFO ][foo.bar] This is a test message
#

Datadog上で確認

ログの時刻が微妙にずれましたが、これはDate Remapperを無効にしたためDatadogが読み取れる時刻がなくなり、Datadogにログが取り込まれた時刻をDateとしているため、時刻が微妙にずれました。
リアルタイムでログを送信している場合はほぼ気になりませんが、細かい部分が気になるあなたは気になりますよね。

9時間引いた値をDate Remapperにかける

上述の手順では時刻が微妙にずれました。そこを解消するために、じゃあ9時間引いた値をDate Remapperにかければ良いじゃないかという方法がこちらになります。

Arithmetic Processorを使用します。こちらの機能はGrok Parserで格納したATTRIBUTESに対し計算を行うことができます。今回の場合は9時間（32400000ミリ秒）引いた値を計算し、timestamp_utcに格納しています。
その後、Date Remapperでtimestamp_utcをDatadogで表示する時刻に変換しています。

どのように変化したのか確認します。時刻がちゃんと合いました！
・ログの日付：2020/4/26/ 21:05:09.000
・Datadog上の時間：2020/4/26/ 21:05:09.000

ログの出力

# echo "[`date "+%FT%T,000"`][INFO ][foo.bar] This is a test message" >> /var/log/elasticsearch/elasticsearch.log
# tail -n 1 /var/log/elasticsearch/elasticsearch.log
[2020-04-26T21:05:09,000][INFO ][foo.bar] This is a test message
#

Datadog上で確認

まとめ

今回はDatadogで時刻がずれる問題を解消するための方法でした。
最初、ログを出力しているにも関わらず表示されず、何で何でと調査している内にこちらの事象が原因と判明しました。時刻がずれると、障害発生からDatadogで通知されるまで9時間かかるなんてことになりかねないので注意が必要です。
以上、Date Remapperの設定でした！