ログの時刻情報について

はじめに

ログを分析や監視に利用する上で外せない情報として、時刻があります。

ログ分析基盤で取り扱うデータは時系列データになりますので
時刻情報について考えないといけないことが多くあります。

【考えること】
・複数ある時刻情報の中でどの時刻情報を用いて分析や監視を行うのか？
・ログの「発生時刻」と「到達時刻」の差がどのくらいあるのか？
・ログの取り込みにおいて、時刻情報のフィルタ処理は必要になるのか？
・時刻情報はどんな時刻フォーマットになっているのか？
・時刻情報のタイムゾーンの取り扱いってどうなっているのか？
などなど。

WindowsのイベントログやLinuxのAuditlogをサンプルにElasticStackにログを取り込み
調べたことを備忘録的に記事にまとめてみました。

利用環境

product	version
logstash	6.6.2
auditbeat	6.6.2
Elasticsearch	6.6.2
kibana	6.6.2
Java	1.8.0

【構成図】

・WinodowsのEventLogはWinlogbeatを使って、Logstash経由でElasticsearchに取り込みます。
・LinuxのAuditLogはAuditbeatを使って、Logstash経由でElasticsearchに取り込みます。

ログの発生時刻と到達時刻とは

まず、Logstashはログを取り込んだ時刻(到達時刻)を@timestampというFieldとして取り扱います。

【参考】
Logstashは取り込むログにLogstashで付与するFieldが既に存在する場合は情報の上書きはされません。
例えば、Auditbeatですでに@timestampが付与されているログをLogstashに渡した場合は
@timestampはAuditbeatで取り込んだ時刻になります。

どうしてもlogstashが取り込んだ時刻が必要な場合は、以下のようなフィルタを書く感じになります。

logstash.confのサンプル

input {
  beats {
    port => 5044
  }
}
filter {
  ruby {
    code => "event.set('logstash_timestamp', Time.now());"
  }
  mutate {
    copy => { "@timestamp" => "beat_timestamp" }
  }
}

ログ時刻情報には発生時刻と到達時刻という2つの時刻情報と向き合う必要があります。
どちらの時刻を分析に利用するかそれぞれにメリット/デメリットがあります。

【発生時刻と到達時間の差が大きくなるケース】
①ログの取り込みがストリーミング処理ではなく、バッチ処理となるケース
②PC端末操作ログにおいて、長い間管理サーバのあるネットワークに接続されていなかったケース
③通信ログにおいて、セッションが長期間にも及ぶようなケース(切断時にログ記録されるため)

ログ分析において、一般的に発生時刻を使いますが、分析タイミングによっては
発生時刻だと見逃してしまう可能性があります。
ログ取り込み時に一定以上の時刻差のあるログの監視を行う必要が出てくると思いました。

ログの時刻フォーマットとは

ログの時刻フォーマットには様々な形式があります。(以下、あくまで一例です)

#	時刻サンプル	フォーマット	利用例
1	2019-05-19T18:00:00.000Z	ISO8601	Windows EventLog
2	1558256400	UNIX時間	Linux AuditLog
3	May 19 18:00:00	RFC 3164	Linux Syslog
4	2019/05/19 18:00:00	yyyy/MM/dd HH: mm:ss	多数

日付と時刻が異なるFieldになっている場合もあります。
ログ出力時刻(月): May, ログ出力時刻(日): 19, ログ出力時刻(時刻): 18:00:00

異なるフォーマットの時刻情報を解析するのが、LogstashのDate Filter pluginになります。

【参考】
・ISO8601とは
・UNIX時間とは
・RFC3164とは

Date Filter Pluginとは

ログのField(主に時刻情報が値に含まれているもの)をmatchで指定して、指定したフォーマットで型取りして
その時刻情報を分析のタイムスタンプとして利用するためのフィルタになります。

※Date Filter固有の設定項目は以下の通りです。

設定項目	デフォルト値	説明
locale	- (任意)	日付情報の解析に使用されるロケールを指定します。※1、※2
match	[] (任意)	日付フィールドとフォーマットパターンを配列で指定します。
tag_on_failure	["_dateparsefailure"] (任意)	パース失敗時にtagsに追加する値を指定します。
target	@timestamp (任意)	一致した日付情報を格納するField名を指定します。
timezone	- (任意)	日付情報の解析に使用されるタイムゾーンを指定します。※1、※3

※1 localeとtimezoneは何も設定しないとOSが保持しているパラメータを利用します。
※2 MonやJanなど英語表記の曜日や月の情報を認識させるために利用します。
※3 UNIX時間やISO8601のような時刻情報でタイムゾーンが判断出来ない場合に利用します。

【Date Filter Pluginの主な利用方法】
①ログ発生時刻を@timestampに置き換えて、発生時刻ベースの分析を行う
②String型の時刻が含まれるFieldを値をDate型に変換して、時刻情報として分析に利用する

【サンプル】
・timestampというFieldの時刻情報を@timestampとするFilterです。

logstash.confの抜粋

  date {
    match => [ "timestamp", "dd/MMM/yyyy:HH:mm:ss", "d/MMM/yyyy:HH:mm:ss" ] #フォーマットを配列で記載
    locale => "en"
    timezone => "Asia/Tokyo"
    tag_on_failure => ["_dateparsefailure"] #省略可
    target => @timestamp #省略可
    remove_field => [ "timestamp" ] #不要になった元のFieldを削除
  }

Date Filter Pluginで処理出来ないような場合は、基本的にRuby Filter Pluginのお世話になると考えておくのが
良さそうです。(例: Elasticsearchのタイムゾーン問題)

タイムゾーンについて

日本時刻とズレない限りあまり気にすることのないタイムゾーンについて
システムが生成ログ時間はUTCで保持しています。
(OSタイムゾーンをJST +09:00にしているから意識しませんよね、、)

例えば、WindowsのEventLogですが、日付と時刻という項目はOSタイムゾーンで表示されますが
TimeCreatedの時刻は、[SystemTime]としてISO8601形式のZ付きのUTC時間で保持しています。
※WinlogbeatもこのUTC時間を取得し、@timestampとしています。

もう1つ、LinuxのAudit Logですが、こちらもUNIX時間(1557279001.251)で持っているため、UTC時間で保持しています。dateコマンドでJST表示されますが、@timestampにはtimedatectlコマンドのUniversal timeで時刻情報を渡しているはずです。

[root@ip-10-0-0-71 ec2-user]# timedatectl
      Local time: 水 2019-05-08 10:32:03 JST
  Universal time: 水 2019-05-08 01:32:03 UTC
        RTC time: 水 2019-05-08 01:31:55
       Time zone: Asia/Tokyo (JST, +0900)
     NTP enabled: yes
NTP synchronized: no
 RTC in local TZ: no
      DST active: n/a
[root@ip-10-0-0-71 ec2-user]# date
2019年  5月  8日 水曜日 10:32:05 JST

[root@ip-10-0-0-71 ec2-user]# tail -f /var/log/audit/audit.log
type=USER_END msg=audit(1557279001.251:20160): pid=29449 uid=0 auid=0 ses=2728 msg='op=PAM:session_close grantors=pam_loginuid,pam_keyinit,pam_limits,pam_systemd acct="root" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success'

上記のAudit LogをElasticsearchに取り込み、KibanaのDiscover画面で見てみました。
Table表示で見た場合とJSON表示で見た場合の比較は以下の通りです。

【Table表示】

【JSON表示】

Table表示の場合、日本時間で表示されているのに対して、JSON表示の場合はISO8601(Z付き)のUTC時間で表示されます。Elasticsearchに格納されているDocumentの@timestampはUTCで保持されているということですね。それをKibanaで表示する時はブラウザが認識しているタイムゾーンで表示することで人間が正しく理解出来るようにしているということですね。

まとめ

ログの時刻情報を通して、システムがどのように時刻を取り扱っているのか深堀してみました。
基本的にはUTC時間で情報を保持しているが、人間に見せる時にだけタイムゾーンに合わせている
ということですね。(当たり前と言えば当たり前なんですが、、)

複数のタイムゾーンにまたがる国ではどのようにシステムのアクセスログ等を取り扱っているのか
気になってきます。ロシアや中国、アメリカ等、東西に広い国では少し緯度経度が変われば
タイムゾーンも変わってきそうですし、Webのアクセスログの解析するには緯度経度を加味しないと
正しいWebのアクセス解析が出来ないような気がしました。