[Still Not Solved!] Filebeat cannot recognize timezone in syslog

I THOUGHT THE PROBLEM HAS BEEN SOLVED, BUT IS'T NOT!

###########

Original Question:

I'm using filebeat to harvest logs directly to ES.

The timezone on my server is UTC +08:00 (Asia/Shanghai).

I used filebeat modules enable system elasticsearch kibana to configure filebeat to ingest Elasticsearch logs.

Everything worked fine, except a wierd problem: the kibana incorrectly displayed the timestamp. It moves 8 hours forward into the future.

Picture below shows the problem I met: the red line is the current time, and the '@timestamp' of every single syslog has been displayed 8 hours forward.

I read the JSON document and I found that the @timestamp is stored in UTC+8, which should be stored in UTC.

It's so weird!

The logs in apache, mysql, and elastic server have a correct @timestamp value. While the logs in system, elasticsearch are incorrect. For now.

This is the JSON struct of a single document:

{
  "_index": "filebeat-7.2.0-2019.07.28-000001",
  "_type": "_doc",
  "_id": "qRLNPWwBaHGrHZ27tQUU",
  "_version": 1,
  "_score": null,
  "_source": {
    "agent": {
      "hostname": "bigiron",
      "id": "3eb06835-b68e-4b25-9ec1-1ebf0bac83a3",
      "ephemeral_id": "fd8648df-4eab-4fd2-b915-97fb631211b6",
      "type": "filebeat",
      "version": "7.2.0"
    },
    "process": {
      "name": "filebeat",
      "pid": 28369
    },
    "log": {
      "file": {
        "path": "/var/log/syslog"
      },
      "offset": 1964308
    },
    "fileset": {
      "name": "syslog"
    },
    "message": "2019-07-29T20:56:14.994+0800#011INFO#011log/harvester.go:253#011Harvester started for file: /var/log/apache2/access.log",
    "cloud": {
      "availability_zone": "cn-beijing-a",
      "instance": {
        "id": "i-2ze74ci7j8m68giheosd"
      },
      "provider": "ecs",
      "region": "cn-beijing"
    },
    "input": {
      "type": "log"
    },
    "@timestamp": "2019-07-29T20:56:14.000Z",
    "system": {
      "syslog": {}
    },
    "ecs": {
      "version": "1.0.0"
    },
    "service": {
      "type": "system"
    },
    "host": {
      "hostname": "bigiron",
      "os": {
        "kernel": "4.4.0-146-generic",
        "codename": "xenial",
        "name": "Ubuntu",
        "family": "debian",
        "version": "16.04.6 LTS (Xenial Xerus)",
        "platform": "ubuntu"
      },
      "containerized": false,
      "name": "bigiron",
      "id": "a76d0b1176a3140a8e07cb725964722b",
      "architecture": "x86_64"
    },
    "event": {
      "timezone": "+08:00",
      "module": "system",
      "dataset": "system.syslog"
    }
  },
  "fields": {
    "@timestamp": [
      "2019-07-29T20:56:14.000Z"
    ],
    "suricata.eve.timestamp": [
      "2019-07-29T20:56:14.000Z"
    ]
  },
  "sort": [
    1564433774000
  ]
}

###########

Update:

Filebeat cannot recognize the timezone from the log file. It assumes the time in syslog was stored in UTC, which was actually stored in UTC+8.

I tried to enable var.convert_timezone: true in {conf_path}/module.d/system and re-created the pipeline, Still not work.

My server time

UTC+8 2019/07/29 20:56:14

The time in syslog

Jul 29 20:56:14

The @timestamp from filebeat

2019-07-29T20:56:14.000Z

The @timestamp from filebeat should be

2019-07-29T12:56:14.000Z

system.yml:

- module: system
  # Syslog
  syslog:
    enabled: true

    # Set custom paths for the log files. If left empty,
    # Filebeat will choose the paths depending on your OS.
    #var.paths: ["/var/log/syslog*"]

    # Convert the timestamp to UTC. Requires Elasticsearch >= 6.1.
    var.convert_timezone: true

  # Authorization logs
  auth:
    enabled: true

    # Set custom paths for the log files. If left empty,
    # Filebeat will choose the paths depending on your OS.
    #var.paths:

    # Convert the timestamp to UTC. Requires Elasticsearch >= 6.1.
    var.convert_timezone: true

elasticsearch.yml

- module: elasticsearch
  # Server log
  server:
    enabled: true

    # Set custom paths for the log files. If left empty,
    # Filebeat will choose the paths depending on your OS.
    #var.paths:

    # Convert the timestamp to UTC. Requires Elasticsearch >= 6.1.
    var.convert_timezone: true

  gc:
    enabled: false
    # Set custom paths for the log files. If left empty,
    # Filebeat will choose the paths depending on your OS.
    #var.paths:

  audit:
    enabled: true
    # Set custom paths for the log files. If left empty,
    # Filebeat will choose the paths depending on your OS.
    #var.paths:

    # Convert the timestamp to UTC. Requires Elasticsearch >= 6.1.
    var.convert_timezone: true

  slowlog:
    enabled: true
    # Set custom paths for the log files. If left empty,
    # Filebeat will choose the paths depending on your OS.
    #var.paths:

    # Convert the timestamp to UTC. Requires Elasticsearch >= 6.1.
    var.convert_timezone: true

  deprecation:
    enabled: false
    # Set custom paths for the log files. If left empty,
    # Filebeat will choose the paths depending on your OS.
    #var.paths:

    # Convert the timestamp to UTC. Requires Elasticsearch >= 6.1.
    var.convert_timezone: true
1 Like

Do you have I solution for this bug? I don't think I'm the only one.

I don't think there's a bug.
Can you show the full message in JSON for one of the messages?
Kibana shows the time in the browser timezone, which should be your local timezone.

1 Like

Well, you're right. The time in JSON is correct, so what should I do to fix this problem? Here's the JSON document:

{
  "_index": "filebeat-7.2.0-2019.07.28-000001",
  "_type": "_doc",
  "_id": "phGHPWwBaHGrHZ27CuGO",
  "_version": 1,
  "_score": null,
  "_source": {
    "agent": {
      "hostname": "bigiron",
      "id": "3eb06835-b68e-4b25-9ec1-1ebf0bac83a3",
      "type": "filebeat",
      "ephemeral_id": "fd8648df-4eab-4fd2-b915-97fb631211b6",
      "version": "7.2.0"
    },
    "process": {
      "name": "CRON",
      "pid": 28979
    },
    "log": {
      "file": {
        "path": "/var/log/auth.log"
      },
      "offset": 23640
    },
    "fileset": {
      "name": "auth"
    },
    "message": "pam_unix(cron:session): session closed for user root",
    "cloud": {
      "availability_zone": "cn-beijing-a",
      "instance": {
        "id": "i-2ze74ci7j8m68giheosd"
      },
      "provider": "ecs",
      "region": "cn-beijing"
    },
    "input": {
      "type": "log"
    },
    "@timestamp": "2019-07-29T19:39:01.000Z",
    "system": {
      "auth": {}
    },
    "ecs": {
      "version": "1.0.0"
    },
    "service": {
      "type": "system"
    },
    "host": {
      "hostname": "bigiron",
      "os": {
        "kernel": "4.4.0-146-generic",
        "codename": "xenial",
        "name": "Ubuntu",
        "family": "debian",
        "version": "16.04.6 LTS (Xenial Xerus)",
        "platform": "ubuntu"
      },
      "containerized": false,
      "name": "bigiron",
      "id": "a76d0b1176a3140a8e07cb725964722b",
      "architecture": "x86_64"
    },
    "event": {
      "timezone": "+08:00",
      "module": "system",
      "dataset": "system.auth"
    }
  },
  "fields": {
    "@timestamp": [
      "2019-07-29T19:39:01.000Z"
    ],
    "suricata.eve.timestamp": [
      "2019-07-29T19:39:01.000Z"
    ]
  },
  "sort": [
    1564429141000
  ]
}

Do I need to change the kibana setting?

Have you changed any settings in Kibana, in advanced settings or otherwise?

@timestamp field is in UTC, and Kibana shows it in UTC+8.

Nops. I think my @timestamp field is in UTC+8, as it's same to my local timestamp.

Okay, so if the value in @timestamp field is in UTC+8, there's your problem :slight_smile:
It should be in UTC. Then Kibana will convert it from UTC to UTC+8 (in your case) on the fly.

How have you configured filebeat to ingest Elasticsearch logs?

If you mean pre-process, no :joy: I haven't yet.

No, I mean how is the filebeat configured?

I use modules enable command to enable it from the command-line.

Like filebeat modules enable system apache elasticsearch kibana mysql.

I only edit the output.elasticsearch and setup.kibana part in filebeat.yml

Okay, then I don't think I can help you any further. I have never used any modules.
Make sure you are running the latest version of Filebeat, in case of a fixed bug.

I think it's not a problem of modules.

I use local time on my server, I think I can only change my server timezone to UTC to solve this problem.

I will keep trying more methods to solve the timezone problem. Thanks a lot for your help!

hope anyone can help me...

I've just updated my configuration. Could you please have a look?

I think you are right: https://github.com/elastic/beats/issues/9756

Didn’t the convert timezone option fix the issue?

When the timestamps in the original files appear in local time, then the setting var.convert_timezone: true is needed in the module configuration.

Not all modules support this setting, so check the module documentation for that. System module supports it for sure, but I don't see it in Elasticsearch module documentation (although I believe it's available based on https://github.com/elastic/beats/pull/9761).

Anyway, the setting works by adding the timezone information during indexing via an ingest pipeline, so whenever you change this setting, it's very important that you run filebeat once to recreate the ingest pipelines in Elasticsearch, so the new timezone information will be considered during indexing.

To do that you should run something like ./filebeat setup --pipelines --modules system. The pipeline code should be different when convert_timezone is set to true or when it's not set (defaults to false).
More info here: https://www.elastic.co/guide/en/logstash/current/use-ingest-pipelines.html

Take a look at your ingest pipelines (GET _ingest/pipeline). If the pipeline is correct there then it might be a bug, but I would check that first (because for system module I'm almost sure that it works fine).

One way to ensure/check that the pipeline is recreated is deleting it first from Elasticsearch and then restarting Filebeat or running the command I shared before and see in Elasticsearch if the pipeline is created again properly.

Hope it helps!

no, it still not works

I tried to enable var.convert_timezone: true in {conf_path}/module.d/system as I said in the question. And I thought it works.

Then I filtered the data from filebeat and found that some logs are in correct timestamp, some are not.

The logs in apache, mysql, and elastic server have a correct @timestamp value. While the logs in syslog, elasticsearch.log, es_deprecation and es_gc are incorrect.

I've also checked my _ingest/pipeline and I don't think there's any problem in the syslog-pipeline.

"filebeat-7.2.0-system-syslog-pipeline" : {
    "processors" : [
      {
        "grok" : {
          "field" : "message",
          "patterns" : [
            """%{SYSLOGTIMESTAMP:system.syslog.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\[%{POSINT:process.pid:long}\])?: %{GREEDYMULTILINE:system.syslog.message}""",
            "%{SYSLOGTIMESTAMP:system.syslog.timestamp} %{GREEDYMULTILINE:system.syslog.message}",
            """%{TIMESTAMP_ISO8601:system.syslog.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\[%{POSINT:process.pid:long}\])?: %{GREEDYMULTILINE:system.syslog.message}"""
          ],
          "pattern_definitions" : {
            "GREEDYMULTILINE" : "(.|\n)*"
          },
          "ignore_missing" : true
        }
      },
      {
        "remove" : {
          "field" : "message"
        }
      },
      {
        "rename" : {
          "field" : "system.syslog.message",
          "target_field" : "message",
          "ignore_missing" : true
        }
      },
      {
        "date" : {
          "field" : "system.syslog.timestamp",
          "target_field" : "@timestamp",
          "formats" : [
            "MMM  d HH:mm:ss",
            "MMM dd HH:mm:ss",
            "ISO8601"
          ],
          "ignore_failure" : true
        }
      },
      {
        "remove" : {
          "field" : "system.syslog.timestamp"
        }
      }
    ],
    "on_failure" : [
      {
        "set" : {
          "field" : "error.message",
          "value" : "{{ _ingest.on_failure_message }}"
        }
      }
    ],
    "description" : "Pipeline for parsing Syslog messages."
  }

That pipeline is wrong, it doesn't include the timezone information.
Delete that pipeline and just restart filebeat (don't run the ./filebeat setup command...).

If the pipeline is not created run filebeat adding this parameter: -E filebeat.overwrite_pipelines=true.

Share the new pipeline as soon as it's created. If the var.convert_timezone from your config is not ignored, your pipeline should have something like:

    "date": {
          "timezone": "{{ beat.timezone }}",
...
...

I faced once this bug: https://github.com/elastic/beats/issues/9747, where the manual command ignored the timezone setting from the module configuration, but I suppose this should have been fixed in the latest release...