nginxのログをFilebeatで収集してKibanaで見た時エラーログだけ日時がずれた原因調査

環境・バージョン

AWS Workspaces (Amazon Linux 2)
Elasticsearch 7.4.2
Kibana 7.4.2
Filebeat 7.4.2
nginx 1.16.1

結論

先に結論知りたいと思いますので先に言いますと
DockerコンテナのタイムゾーンをデフォルトのUTCから変えていないと問題無し。
Dockerコンテナのタイムゾーンを今回はAsia/Tokyoに変えたことで、nginxの
エラーログがElasticsearchに取り込まれる時に+9時間された日時が登録されました。
アクセスログはDockerコンテナのタイムゾーン変更あり・なしのどちらでも問題無し。

DockerコンテナのタイムゾーンををAsia/Tokyoに変えている場合は、
filebeat.ymlに以下の設定を追加

processors:
 - drop_fields.fields: ['event.timezone']
 - add_fields:
    target: event
    fields:
     timezone:  'Asia/Tokyo'

アクセスログ内の日付には以下のように「+0900」があり、エラーログには無い。この部分も関係があると思われます。

# アクセスログの日付部分:
[01/Dec/2019:20:37:31 +0900] 

# エラーログの日付部分
2019/12/01 20:37:30

調査内容

ディレクトリ構成

/home/sano/dkwork2
　|--es
　|  |--docker-compose.yml
　|  |--es
　|  |  |--config
　|  |  |  |--elasticsearch.yml
　|  |  |--data
　|  |--filebeat
　|  |  |--config
　|  |  |  |--filebeat.yml
　|  |  |  |--nginx.yml
　|--log
　|  |--nginx
　|  |  |--access.log
　|  |  |--error.log
　|--nginx
　|  |--docker-compose.yml

nginxのdocker-compose.yml

version: '3.7'
services:
  web:
    container_name: web
    image: nginx:1.16.1
    ports:
      - 81:80
    volumes:
      - ../log/nginx:/var/log/nginx
    restart: unless-stopped
    environment:
      - "TZ=Asia/Tokyo"

Elasticsearch/Kibanaのdocker-compose.yml

version: '3.7'
services:
  elasticsearch:
    container_name: elasticsearch
    image: docker.elastic.co/elasticsearch/elasticsearch:7.4.2
    volumes:
      - ./es/data:/usr/share/elasticsearch/data
      - ./es/config/elasticsearch.yml:/usr/share/elasticsearch/config/elasticsearch.yml
    ports:
      - 9200:9200
      - 9300:9300
    environment:
      - ES_JAVA_OPTS=-Xms128m -Xmx128m
      - discovery.type=single-node
    restart: unless-stopped

  kibana:
    container_name: kibana
    image: docker.elastic.co/kibana/kibana:7.4.2
    ports:
      - 5601:5601
    depends_on:
      - elasticsearch
    restart: unless-stopped

起動

# Elasticsearch、Kibana
$ cd es
$ mkdir -p es/data
$ chmod 777 es/data
$ docker-compose up -d

# nginx
$ cd ..
$ cd nginx
$ docker-compose up -d

# ダッシュボード、インデックス、インデックスパターンのセットアップ
$ docker run \
--net=es_default \
docker.elastic.co/beats/filebeat:7.4.2 \
setup -E setup.kibana.host=kibana:5601 \
-E output.elasticsearch.hosts=["elasticsearch:9200"]

# Filebeat
$ cd ..
$ cd es
$ docker run -d \
--net=es_default \
--name=filebeat \
--user=root \
--volume="$(pwd)/filebeat/config/filebeat.yml:/usr/share/filebeat/filebeat.yml" \
--volume="$(pwd)/filebeat/config/nginx.yml:/usr/share/filebeat/modules.d/nginx.yml" \
--volume="/home/sano/dkwork2/log/nginx:/var/log/nginx/" \
--volume="/var/lib/docker/containers:/var/lib/docker/containers:ro" \
--volume="/var/run/docker.sock:/var/run/docker.sock:ro" \
docker.elastic.co/beats/filebeat:7.4.2 filebeat -e -strict.perms=false \
-E output.elasticsearch.hosts=["elasticsearch:9200"]

es/config/elasticsearch.yml

cluster.name: "docker-cluster"
network.host: 0.0.0.0
discovery.zen.minimum_master_nodes: 1

# ### x-pack functions
# xpack.security.enabled: false
# xpack.monitoring.enabled: true
# xpack.graph.enabled: false
# xpack.watcher.enabled: false

filebeat/config/filebeat.yml

filebeat.config:
  modules:
    path: ${path.config}/modules.d/*.yml
    reload.enabled: false

processors:
 - drop_fields.fields: ['event.timezone']
 - add_fields:
    target: event
    fields:
     timezone:  'Asia/Tokyo'

output.elasticsearch:
  hosts: ["elasticsearch:9200"]

filebeat/config/nginx.yml

- module: nginx
  access:
    enabled: true
    var.paths: ["/var/log/nginx/access.log*"]
  error:
    enabled: true
    var.paths: ["/var/log/nginx/error.log*"]

タイムゾーンを変更していない場合

・nginxのdocker-compose.ymlに環境変数「TZ」の指定していない状態
・filebeat.ymlにtimezoneの設定追加してない状態

access.logの日付部分

@timestamp　　　　　　　　Dec 1, 2019 @ 19:50:21.000
event.created	        Dec 1, 2019 @ 19:50:24.533
suricata.eve.timestamp	Dec 1, 2019 @ 19:50:21.000
event.timezone　　　　　 +00:00

error.logの日付部分

@timestamp　　　　　　　　Dec 1, 2019 @ 19:50:21.000
event.created	        Dec 1, 2019 @ 19:50:24.532
suricata.eve.timestamp	Dec 1, 2019 @ 19:50:21.000
event.timezone　　　　　 +00:00

タイムゾーンを変更している場合(filebeatの設定は変更なし)

・filebeat.ymlにtimezoneの設定追加してない状態
・nginxのdocker-compose.ymlに以下の設定追加

    environment:
      - "TZ=Asia/Tokyo"

access.logの日付部分

@timestamp　　　　　　　　Dec 2, 2019 @ 04:54:30.000
event.created	        Dec 1, 2019 @ 19:54:39.539
suricata.eve.timestamp	Dec 2, 2019 @ 04:54:30.000
event.timezone　　　　　 +00:00

error.logの日付部分

@timestamp　　　　　　　　Dec 1, 2019 @ 19:54:30.000
event.created	        Dec 1, 2019 @ 19:54:39.538
suricata.eve.timestamp	Dec 1, 2019 @ 19:54:30.000
event.timezone　　　　　 +00:00

タイムゾーンを変更している場合(filebeatの設定は変更あり)

filebeat.ymlに以下の設定を追加

processors:
 - drop_fields.fields: ['event.timezone']
 - add_fields:
    target: event
    fields:
     timezone:  'Asia/Tokyo'

access.logの日付部分

@timestamp　　　　　　　　Dec 1, 2019 @ 20:37:30.000
event.created	        Dec 1, 2019 @ 20:38:12.812
suricata.eve.timestamp	Dec 1, 2019 @ 20:37:30.000
event.timezone　　　　 　Asia/Tokyo

error.logの日付部分

@timestamp　　　　　　　　Dec 1, 2019 @ 20:37:30.000
event.created	        Dec 1, 2019 @ 20:38:12.812
suricata.eve.timestamp	Dec 1, 2019 @ 20:37:30.000
event.timezone　　　　　 Asia/Tokyo

以下は2019/12/3に追記

nginxのDockerコンテナのタイムゾーン「Asia/Tokyo」、FilebeatのDockerコンテナのタイムゾーン「Asia/Tokyo」

・filebeat.ymlにtimezoneの設定追加してない状態
・filebeatのdocker runコマンドは「-e TZ=Asia/Tokyo」を追加して起動

access.logの日付部分

@timestamp　　　　　　　　Dec 3, 2019 @ 00:15:40.000
event.created	        Dec 3, 2019 @ 00:15:45.253
suricata.eve.timestamp	Dec 3, 2019 @ 00:15:40.000
event.timezone　　　　　 +09:00

error.logの日付部分

@timestamp　　　　　　　　Dec 3, 2019 @ 00:15:38.000
event.created	        Dec 3, 2019 @ 00:15:45.253
suricata.eve.timestamp	Dec 3, 2019 @ 00:15:38.000
event.timezone　　　　　 +09:00