1 Hour Difference on showing Logs in ELK/Kibana

radu990 · March 30, 2021, 7:56am

Hello,

I have set a Filebeat agent on a server for Apache logs (using apache module), and observed that the logs are appearing on Kibana/ELK with 1 hour delay.
Any idea what can be the problem? The time/timezone settings are correct on both ELK/Kibana and server in case. Checking the apache logs directly on the server displays ok all the logs, with the corect time. But ELK/Kibana will show them only 1 hour later.
Observed that there is a difference in timestamp and event.created/event.ingested. Maybe it's related...

radu990 · April 2, 2021, 8:56am

Anybody? Any ideas why it happens so?
I've compared with other servers where everything works well. Same timezone is used, same settings everywhere in filebeat.

Removed filebeat with manually removing all folders/files related to filebeat, and same delay happens after reinstalling and configuring from scratch.

dadoonet · April 2, 2021, 9:05am

I can see that the @timestamp field does not seem to contain any TZ indication.
But could you share a json document so we can check the exact values in the JSON document?

Did you see this? Apache module | Filebeat Reference [8.11] | Elastic

This module parses logs that don’t contain time zone information. For these logs, Filebeat reads the local time zone and uses it when parsing to convert the timestamp to UTC. The time zone to be used for parsing is included in the event in the event.timezone field.

To disable this conversion, the event.timezone field can be removed with the drop_fields processor.

If logs are originated from systems or applications with a different time zone to the local one, the event.timezone field can be overwritten with the original time zone using the add_fields processor.

radu990 · April 2, 2021, 9:15am

Sure, please see below an example of a JSON document

{
  "_index": "filebeat-7.12.0-2021.03.30-000001",
  "_type": "_doc",
  "_id": "OT2akXgBrNnms5-qprv7",
  "_version": 1,
  "_score": null,
  "_source": {
    "agent": {
      "hostname": "domain.com",
      "name": "domain.com",
      "id": "1f0e7b95-79a1-41f1-9923-ddb2eee399d0",
      "type": "filebeat",
      "ephemeral_id": "ff5d0cdb-2875-4e65-95b2-3c2b98c96ba4",
      "version": "7.12.0"
    },
    "log": {
      "file": {
        "path": "/local/notesdata/weblogs/access04022021.log"
      },
      "offset": 4378390
    },
    "destination": {
      "domain": "domain.com"
    },
    "source": {
      "ip": "10.0.0.5"
    },
    "fileset": {
      "name": "access"
    },
    "url": {
      "original": "/ADB/revenues.nsf/icon11.gif"
    },
    "input": {
      "type": "log"
    },
    "apache": {
      "access": {}
    },
    "@timestamp": "2021-04-02T09:02:06.000Z",
    "ecs": {
      "version": "1.8.0"
    },
    "service": {
      "type": "apache"
    },
    "host": {
      "hostname": "domain.com",
      "os": {
        "kernel": "2.6.32-573.18.1.el6.x86_64",
        "codename": "Final",
        "name": "CentOS",
        "family": "redhat",
        "type": "linux",
        "version": "6.7 (Final)",
        "platform": "centos"
      },
      "containerized": false,
      "ip": [
        "192.168.1.60",
        "fe80::215:5dff:fe01:3301"
      ],
      "name": "domain.com",
      "id": "41d334d3044ca22a1daa6aae00000022",
      "mac": [
        "00:15:5d:01:33:01"
      ],
      "architecture": "x86_64"
    },
    "http": {
      "request": {
        "referrer": "https://domain.com/",
        "method": "GET"
      },
      "response": {
        "status_code": 200,
        "body": {
          "bytes": 1403
        }
      },
      "version": "1.1"
    },
    "event": {
      "ingested": "2021-04-02T08:02:14.846051490Z",
      "kind": "event",
      "created": "2021-04-02T08:02:13.801Z",
      "module": "apache",
      "category": "web",
      "dataset": "apache.access",
      "outcome": "success"
    },
    "user_agent": {
      "original": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.90 Safari/537.36",
      "os": {
        "name": "Windows",
        "version": "10",
        "full": "Windows 10"
      },
      "name": "Chrome",
      "device": {
        "name": "Other"
      },
      "version": "89.0.4389.90"
    },
    "username": "User/O=Domain/C=CZ"
  },
  "fields": {
    "event.ingested": [
      "2021-04-02T08:02:14.846Z"
    ],
    "@timestamp": [
      "2021-04-02T09:02:06.000Z"
    ],
    "event.created": [
      "2021-04-02T08:02:13.801Z"
    ]
  },
  "highlight": {
    "suricata.eve.http.url": [
      "@kibana-highlighted-field@/ADB/revenues.nsf/icon11.gif@/kibana-highlighted-field@"
    ],
    "url.original": [
      "@kibana-highlighted-field@/ADB/revenues.nsf/icon11.gif@/kibana-highlighted-field@"
    ],
    "host.hostname": [
      "@kibana-highlighted-field@domain.com@/kibana-highlighted-field@"
    ]
  },
  "sort": [
    1617350534846
  ]
}

radu990 · April 2, 2021, 9:17am

My current Apache pipeline.yml . I don't see anything related to event.timezone there

[root@server]# cat /usr/share/filebeat/module/apache/access/ingest/pi                                                                                                                                                             peline.yml
description: "Pipeline for parsing Apache HTTP Server access logs. Requires the                                                                                                                                                              geoip and user_agent plugins."

processors:
- set:
    field: event.ingested
    value: '{{_ingest.timestamp}}'
- grok:
    field: message
    patterns:
    - '%{IPORHOST:destination.domain} %{IPORHOST:source.ip} - %{DATA:user.name}                                                                                                                                                              \[%{HTTPDATE:apache.access.time}\]
      "(?:%{WORD:http.request.method} %{DATA:url.original} HTTP/%{NUMBER:http.ve                                                                                                                                                             rsion}|-)?"
      %{NUMBER:http.response.status_code:long} (?:%{NUMBER:http.response.body.by                                                                                                                                                             tes:long}|-)(
      "%{DATA:http.request.referrer}")?( "%{DATA:user_agent.original}")?'
    - '%{IPORHOST:source.address} - %{DATA:user.name} \[%{HTTPDATE:apache.access                                                                                                                                                             .time}\]
      "(?:%{WORD:http.request.method} %{DATA:url.original} HTTP/%{NUMBER:http.ve                                                                                                                                                             rsion}|-)?"
      %{NUMBER:http.response.status_code:long} (?:%{NUMBER:http.response.body.by                                                                                                                                                             tes:long}|-)(
      "%{DATA:http.request.referrer}")?( "%{DATA:user_agent.original}")?'
    - '%{IPORHOST:source.address} - %{DATA:user.name} \[%{HTTPDATE:apache.access                                                                                                                                                             .time}\]
      "-" %{NUMBER:http.response.status_code:long} -'
    - \[%{HTTPDATE:apache.access.time}\] %{IPORHOST:source.address} %{DATA:apach                                                                                                                                                             e.access.ssl.protocol}
      %{DATA:apache.access.ssl.cipher} "%{WORD:http.request.method} %{DATA:url.o                                                                                                                                                             riginal}
      HTTP/%{NUMBER:http.version}" (-|%{NUMBER:http.response.body.bytes:long})
    - '%{IPORHOST:source.ip} (%{IPORHOST:destination.domain}.*|.*) ("CN=%{DATA:u                                                                                                                                                             sername}"|"%{DATA:username}"|-) \[%{HTTPDATE:apache.access.time}\] "(?:%{WORD:ht                                                                                                                                                             tp.request.method} %{DATA:url.original} HTTP/%{NUMBER:http.version}|-|%{GREEDYDA                                                                                                                                                             TA:url.original})?" %{NUMBER:http.response.status_code:long} (?:%{NUMBER:http.re                                                                                                                                                             sponse.body.bytes:long}|-) ("%{DATA:http.request.referrer}") ("%{DATA:user_agent                                                                                                                                                             .original}")'
    - '%{IPORHOST:source.ip} (%{IPORHOST:destination.domain}.*|.*) - \[%{HTTPDAT                                                                                                                                                             E:apache.access.time}\] "(?:%{WORD:http.request.method} %{DATA:url.original} HTT                                                                                                                                                             P/%{NUMBER:http.version}|-|%{GREEDYDATA:url.original})?" %{NUMBER:http.response.                                                                                                                                                             status_code:long} (?:%{NUMBER:http.response.body.bytes:long}|-) ("%{DATA:http.re                                                                                                                                                             quest.referrer}") ("%{DATA:user_agent.original}") (?:%{NUMBER:aliator}|-) (\".*I                                                                                                                                                             NOTES_LOGIN_ID=%{DATA:username}|.*\")'
    ignore_missing: true
- remove:
    field: message
- set:
    field: event.kind
    value: event
- set:
    field: event.category
    value: web
- set:
    field: event.outcome
    value: success
    if: "ctx?.http?.response?.status_code != null && ctx.http.response.status_co                                                                                                                                                             de < 400"
- set:
    field: event.outcome
    value: failure
    if: "ctx?.http?.response?.status_code != null && ctx.http.response.status_co                                                                                                                                                             de > 399"
- grok:
    field: source.address
    ignore_missing: true
    patterns:
    - ^(%{IP:source.ip}|%{HOSTNAME:source.domain})$
- rename:
    field: '@timestamp'
    target_field: event.created
- date:
    field: apache.access.time
    target_field: '@timestamp'
    formats:
    - dd/MMM/yyyy:H:m:s Z
    ignore_failure: true
- remove:
    field: apache.access.time
    ignore_failure: true
- user_agent:
    field: user_agent.original
    ignore_failure: true
- geoip:
    field: source.ip
    target_field: source.geo
    ignore_missing: true
- geoip:
    database_file: GeoLite2-ASN.mmdb
    field: source.ip
    target_field: source.as
    properties:
    - asn
    - organization_name
    ignore_missing: true
- rename:
    field: source.as.asn
    target_field: source.as.number
    ignore_missing: true
- rename:
    field: source.as.organization_name
    target_field: source.as.organization.name
    ignore_missing: true
- set:
    field: tls.cipher
    value: '{{apache.access.ssl.cipher}}'
    ignore_empty_value: true

- script:
    lang: painless
    if: ctx?.apache?.access?.ssl?.protocol != null
    source: >-
      def parts = ctx.apache.access.ssl.protocol.toLowerCase().splitOnToken("v")                                                                                                                                                             ;
      if (parts.length != 2) {
        return;
      }
      if (parts[1].contains(".")) {
        ctx.tls.version = parts[1];
      } else {
        ctx.tls.version = parts[1] + ".0";
      }
      ctx.tls.version_protocol = parts[0];

on_failure:
- set:
    field: error.message
    value: '{{ _ingest.on_failure_message }}'

dadoonet · April 2, 2021, 9:34am

What is the exact Apache log line which correspond to this event?
What was you local date when this event happened?
What is your current timezone?

radu990 · April 2, 2021, 11:20am

Log entry

10.0.0.5 domain.com "CN=User/O=Company/C=CZ" [02/Apr/2021:10:02:06 +0100] "GET /ADB/revenues.nsf/icon11.gif HTTP/1.1" 200 1403 "https://domain.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.90 Safari/537.36" 139857020059654 "_ga=GA1.2.52431859.1517219938; SessionID=ID; __unam=7639673-16ef00748db-277e59b2-92; fpestid=ID; LtpaToken2=TOKEN; LtpaToken=TOKEN" "/local/notesdata/ADB/revenues.nsf"

Server time/timezone is under CEST, so the date was
[root@server ]# date
Fri Apr 2 10:02:06 CEST 2021

dadoonet · April 2, 2021, 1:27pm

So 02/Apr/2021:10:02:06 +0100 contains a timezone value and is stored in apache.access.time.

The thing is that Fri Apr 2 10:02:06 CEST 2021 is actually 02/Apr/2021:10:02:06 +0200 as we switched from CET (GMT+1) to CEST (GMT+2) some days ago.

So I think that the problem is in the source. I mean in Apache logs.
The Apache server is not generating the right information.

The log line should have been something like:

10.0.0.5 domain.com "CN=User/O=Company/C=CZ" [02/Apr/2021:10:02:06 +0200] "GET /ADB/revenues.nsf/icon11.gif HTTP/1.1" 200 1403 "https://domain.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.90 Safari/537.36" 139857020059654 "_ga=GA1.2.52431859.1517219938; SessionID=ID; __unam=7639673-16ef00748db-277e59b2-92; fpestid=ID; LtpaToken2=TOKEN; LtpaToken=TOKEN" "/local/notesdata/ADB/revenues.nsf"

radu990 · April 2, 2021, 1:39pm

Thank you very much for your reply.
I have just checked other servers with Apache which works ok in ELK/Kibana GUI. They have the following (please see the image below). So CEST is still with GMT +1 in logs, and they are displayed ok in ELK. I'm totally lost

dadoonet · April 2, 2021, 1:51pm

I don't know...

But do we agree that 02/Apr/2021:10:02:06 +0100 is incorrect? If so, I'd try to fix that first.

radu990 · April 2, 2021, 1:59pm

Yes, will try to change it to GMT +2 (+200) in the logs. Hopefully there will be changes afterwards.

radu990 · April 6, 2021, 8:24am

Thank you very much @dadoonet for the hint with the timezone. Changed to Africa/Cairo timezone instead of CEST, and now the logs are with +200 (GMT +2) and are working/displayed fine in ELK/Kibana.

system · May 4, 2021, 8:24am

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

Topic		Replies	Views
Wrong Kibana timestamp Kibana	7	649	October 6, 2020
Filebeat timestamp is shown with a 4hr offset Elasticsearch	4	160	October 20, 2023
[Still Not Solved!] Filebeat cannot recognize timezone in syslog Beats filebeat	25	5586	August 28, 2019
Filebeat harvests log from elasticsearch and store field 'timestamp' without converting to utc time Beats elastic-stack-monitoring , filebeat	4	584	February 14, 2019
Two timezones in JSON log Beats filebeat	8	1723	February 22, 2018

1 Hour Difference on showing Logs in ELK/Kibana

Related topics