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