Filebeat 6.2.1 system module does not convert timestamp with timezone


(Bruno Lavoie) #1

Hello,

It seems that Filebeat system module is wrongly converting timestamp into Elaticsearch/Kibana.

While testing all this, I delete all beat indices in my ES to see only new events.

When looking inside Kibana I see brand new events coming at the good time and some are 5 hours past while they're happening right now.

The bad converted ones are from /var/log/messages and /var/log/secure while the good ones are from /var/log/audit/audit.log.

So, it seems that's something bad with the system module.

When looking at _source, the timestamp is stored as-is into Elasticsearch:
{
"_index": "filebeat-6.2.1-2018.02.13",
"_type": "doc",
"_id": "HEPLj2EB_od01kRuTD8r",
"_version": 1,
"_score": null,
"_source": {
"@timestamp": "2018-02-13T10:31:52.000Z",
"system": {
"syslog": {
"hostname": "localhost",
"pid": "621",
"program": "dbus",
"message": "[system] Successfully activated service 'org.freedesktop.nm_dispatcher'",
"timestamp": "Feb 13 10:31:52"
}
},
"offset": 70318,
"beat": {
"hostname": "localhost.localdomain",
"name": "localhost.localdomain",
"version": "6.2.1"
},
"prospector": {
"type": "log"
},
"source": "/var/log/messages",
"fileset": {
"module": "system",
"name": "syslog"
}
},
"fields": {
"@timestamp": [
"2018-02-13T10:31:52.000Z"
]
},
"sort": [
1518517912000
]
}

So it is normal that Kibana shows it 5 hours back by doing the right conversion. To overcome that, I saw that setting var.convert_timezone to true could fix the thing.

When doing that, the problem is the same but there's only a new field added to the source (beat.timezone):
{
"_index": "filebeat-6.2.1-2018.02.13",
"_type": "doc",
"_id": "4kPUj2EB_od01kRuxEF4",
"_version": 1,
"_score": null,
"_source": {
"@timestamp": "2018-02-13T10:42:12.000Z",
"system": {
"syslog": {
"hostname": "localhost",
"program": "systemd-logind",
"message": "New session 21 of user root.",
"timestamp": "Feb 13 10:42:12"
}
},
"offset": 70734,
"beat": {
"hostname": "localhost.localdomain",
"timezone": "-05:00",
"name": "localhost.localdomain",
"version": "6.2.1"
},
"prospector": {
"type": "log"
},
"source": "/var/log/messages",
"fileset": {
"module": "system",
"name": "syslog"
}
},
"fields": {
"@timestamp": [
"2018-02-13T10:42:12.000Z"
]
},
"sort": [
1518518532000
]
}

While reading the convert_timezone option documentation it clearly states that the conversion should happen when using >6.1:

If this option is enabled, Filebeat reads the local timezone and uses it at log parsing time to convert the timestamp to UTC. The local timezone is also added in each event in a dedicated field (beat.timezone). The conversion is only possible in Elasticsearch >= 6.1. If the Elasticsearch version is less than 6.1, the beat.timezone field is added, but the conversion to UTC is not made. The default is false.

But it isn't...

  • Is it a filebeat system module bug?
  • Why this convert timezone option only available to system module and not to others? The others modules handle it correctly and every logs on my system are on my timezone.

When looking at correctly converted events, the @timestamp field is converted to UTC:
{
"_index": "filebeat-6.2.1-2018.02.13",
"_type": "doc",
"_id": "3kPUj2EB_od01kRuxEF4",
"_version": 1,
"_score": null,
"_source": {
"@timestamp": "2018-02-13T15:42:12.622Z",
"offset": 1252095,
"beat": {
"hostname": "localhost.localdomain",
"name": "localhost.localdomain",
"version": "6.2.1"
},
"prospector": {
"type": "log"
},
"source": "/var/log/audit/audit.log",
"fileset": {
"module": "auditd",
"name": "log"
},
"auditd": {
"log": {
"msg": "op=PAM:setcred",
"ses": "21",
"res": "success",
"auid": "0",
"pid": "9375",
"terminal": "ssh",
"record_type": "CRED_REFR",
"sequence": 883,
"uid": "0",
"hostname": "gateway",
"exe": "/usr/sbin/sshd",
"subj": "unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023",
"addr": "192.168.100.1",
"grantors": "pam_env,pam_unix",
"acct": "root"
}
}
},
"fields": {
"@timestamp": [
"2018-02-13T15:42:12.622Z"
]
},
"sort": [
1518536532622
]
}

Facts:

  • CentOS 7 - all available patches installed

  • Elastic Stack 6.2.1 - Filebeat --> ES --> Kibana

  • Current timezone is EST

    [root@localhost ~]# date +'%Z %z'
    EST -0500
    [root@localhost ~]# date
    Tue Feb 13 10:31:30 EST 2018

  • Activated modules: auditd + system

The problem is easily to reproduce as I reinstalled a fresh VM to test it.

What am I missing?

Thanks
Bruno


(Adrian Serrano) #2

The way the convert_timezone feature works is by installing an Elasticsearch ingest pipeline to do this conversion. Unfortunately, if a previous ingest pipeline already exists, filebeat will not update it with the required changes to make convert_timezone work.

You need to delete the existing pipeline manually and restart filebeat:

curl -XDELETE 'http://elasticsearch:9200/_ingest/pipeline/filebeat-*'

Syslog Dashboard Timezone Issue?
Time incorrect from system module (syslog)
Filebeats 6.2.3 system module not sending logs
(Bruno Lavoie) #3

Ok, well, wasn't aware that it was an ingest pipeline on Elasticsearch.
Always though that was done on Filebeat part.

So the first time we start Filebeat, system module settings must be OK...

Just tested by deleting the pipeline an it's now ok.

In the future, if we send logs to logstash before Elasticsearch, is the process the same?

Thanks
Bruno


(system) #4

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.