Logstash has a lag in pushing events to Elastic

logstash config

input {
  file {
    path => "C:/Program Files (x86)/db/Server/logs/oracle.log"
    type => "localhost_access_log"
    start_position => "beginning"
	ignore_older => 86400   # ignore files older than 24 hours
    close_older => 86400  # free the resources
	sincedb_path => "C:\setup\tools\logstash\logstash-8.17.0\logs\oracle_log.sincedb"
  }
  file {
    path => "C:/Program Files (x86)/db/Server/logs/system.log"
    type => "system"
    codec => multiline {
      pattern => "^%{TIMESTAMP_ISO8601}"
      negate => true
      what => "previous"
      charset => "ISO-8859-1"
    }
    start_position => "beginning"
	ignore_older => 86400   # ignore files older than 24 hours
    close_older => 86400  # free the resources
	sincedb_path => "C:\setup\tools\logstash\logstash-8.17.0\logs\system.sincedb"
  }
}

filter {
   if [type] == "localhost_access_log" {
    grok {
      match => {"message" => "\[%{HTTPDATE:logtimeStamp}\] %{IP:hostip} %{URIPROTO:method} %{URIPATH:post-data} (?:%{NOTSPACE:queryparam}|-) %{NUMBER:useragent} %{NUMBER:responsestatus} \[%{GREEDYDATA:message}\] - %{NUMBER:time-taken:int}"}
      overwrite => [ "message"]
    }
    mutate {
      remove_field => [ "logtimeStamp" ]
    }
  }
  if [type] == "system" {
    mutate {
      gsub => [
        "message", "\[\] ", " ",
        "message", "\- ", " ",
        "message", "\s+", " "
      ]
    }
    mutate {
      strip => ["message"]
    }
    grok {
      match => {"message" => ["%{TIMESTAMP_ISO8601:logtimeStamp} %{WORD:loglevel} \[%{USERNAME:httpcall}] %{USERNAME:dbName} %{USERNAME:tenantGuid} %{INT:tenantId} %{INT:userId} %{USERNAME:sessionID} %{GREEDYDATA:message}",
                              "%{TIMESTAMP_ISO8601:logtimeStamp} %{WORD:loglevel} %{GREEDYDATA:message}" ]}
      overwrite => [ "message" ]
    }
    mutate {
      remove_field => [ "logtimeStamp" ]
    }
  }
 
}
output {
    elastic {
      ecs_compatibility => disabled
      hosts => ["https://${**********}:443"]
      ssl => true
      index => "${NODE_ROLE}-%{+YYYY.MM.dd}"
	  document_id => "%{fingerprint}"
    }
  }
}

While running logstash I have identified the issue with lag.

log message: Why it is sending the log 5 hours late?
Issue is happening with windows instance. It has hava heap memory set to 4G.

[2025-02-19T10:22:58,795][DEBUG][logstash.filters.grok    ][main][40e2ddf7bf9bfcdd3a98f5f146527cc76da83c1955901bbe12a47cbd6a078fa9] Event now:  {:event=>{"loglevel"=>"DEBUG", "host"=>{"name"=>"web-server"}, "@timestamp"=>2025-02-19T10:22:58.743645800Z, "nodeRole"=>"web-server-1", "event"=>{"original"=>"2025-02-19T05:13:17,823 DEBUG [scheduler-TaskQueueEngine-thread-231] jdbc.sqlonly       - select TenantId, Name, Uid, DefaultLocale, PartnerUID, Guid from [OracleTenant]  where [OracleTenant].[TenantId]=(int)1\r"}, "message"=>"[scheduler-TaskQueueEngine-thread-231] jdbc.sqlonly select TenantId, Name, Uid, DefaultLocale, PartnerUID, Guid from [OracleTenant] where [OracleTenant].[TenantId]=(int)1", "log"=>{"file"=>{"path"=>"C:/Program Files (x86)/db/Server/logs/system.log"}}

Maybe your LS is in different zone or you are not converting the logtimeStamp field to date and also you have deleted it.

I see this in sincedb. This is file which is been sent again.

C:\setup\tools\logstash\logstash-8.17.0\logs\system.sincedb


3336151636-287522-262144 0 0 369559 1739945755.935 C:/Program Files (x86)/db/Server/logs/system.log
3336151636-375609-2162688 0 0 858170 1740061908.87 C:/Program Files (x86)/db/Server/logs/system.log

There was a file system.log that got renamed to system_2025_19_2.log

how to fix this issue with sincedb?

How and where did you identify this delay?

[2025-02-19T10:22:58,795][DEBUG][logstash.filters.grok    ][main][40e2ddf7bf9bfcdd3a98f5f146527cc76da83c1955901bbe12a47cbd6a078fa9] Event now:  {:event=>{"loglevel"=>"DEBUG", "host"=>{"name"=>"web-server"}, "@timestamp"=>2025-02-19T10:22:58.743645800Z, "nodeRole"=>"web-server-1", "event"=>{"original"=>"2025-02-19T05:13:17,823 DEBUG [scheduler-TaskQueueEngine-thread-231] jdbc.sqlonly       - select TenantId, Name, Uid, DefaultLocale, PartnerUID, Guid from [OracleTenant]  where [OracleTenant].[TenantId]=(int)1\r"}, "message"=>"[scheduler-TaskQueueEngine-thread-231] jdbc.sqlonly select TenantId, Name, Uid, DefaultLocale, PartnerUID, Guid from [OracleTenant] where [OracleTenant].[TenantId]=(int)1", "log"=>{"file"=>{"path"=>"C:/Program Files (x86)/db/Server/logs/system.log"}}

the above is the debug message from logstash

logstash process time 2025-02-19T10:22:58
event which it picked from the above log file 2025-02-19T05:13:17,823

2025-02-19T05:13:17,823 DEBUG [scheduler-TaskQueueEngine-thread-231] jdbc.sqlonly       - select TenantId, Name, Uid, DefaultLocale, PartnerUID, Guid from [OracleTenant]  where [OracleTenant].[TenantId]=(int)1\r"}, "message"=>"[scheduler-TaskQueueEngine-thread-231] jdbc.sqlonly select TenantId, Name, Uid, DefaultLocale, PartnerUID, Guid from [OracleTenant] where [OracleTenant].[TenantId]=(int)1

Yeah, but what is the timezone of the date in the file?

There is no information in the timestamp, so it is not clear that this time is in UTC.

You need to confirm what is the timezone that the application that is writing those logs is using.

@leandrojmp All are in UTC.

please advise.

Can you provide a line from the oracle.log or system.log?

@Rios @leandrojmp please find the logs from the original log file.

system.log
[20/Feb/2025:00:01:47 +0000] 10.3.185.541 GET /Core/ready-status HTTP/1.1 18 200 [https-jsse-nio-443-exec-16] [-] - 0ms

oracle.log

2025-02-20T15:07:49,058 INFO  [https-jsse-nio-443-exec-4] servlet.ReadyStatusServlet    - doGet call for ReadyStatusServlet. Calling doPost.
2025-02-20T15:07:49,480 INFO  [https-jsse-nio-443-exec-5] servlet.ReadyStatusServlet    - doGet call for ReadyStatusServlet. Calling doPost.
2025-02-20T15:07:50,101 INFO  [https-jsse-nio-443-exec-2] servlet.ReadyStatusServlet    - doGet call for ReadyStatusServlet. Calling doPost.

Any thoughts why is this happening?

are you sitting in Eastern time zone? which has five hour different from UTC

yes we are using EST.

If you see logstash is reading older file. That is the issue. Sharing the screenshot from kibana.

image

this is I suspect. when you read a time from logfile using logstash it does not have timezone. and hence elastic is converting ( moving 5 hour) and putting it as ust. now when you see that on kibana it display wrong time.

try this

date { match => ["time_field_name", "dd-MM-yy HH:mm:ss", "dd-MMM-yy HH:mm:ss", "ISO8601"] --> make sure this format matches your date format
        timezone => "EST"  --> make sure this is correct 
        target => "time_field_name"
}

if this does not work try
timezone = "Etc/UTC"

Your grok pattern should be changed.

$ systemlog

input {
  generator { 
    message =>   [ '[20/Feb/2025:00:01:47 +0000] 10.3.185.541 GET /Core/ready-status HTTP/1.1 18 200 [https-jsse-nio-443-exec-16] [-] - 0ms' ]
    count => 1 } 
}
output {
 stdout {codec => rubydebug}
}
filter {
  grok { match => { "message" => "\[%{HAPROXYDATE:[@metadata][timestamp]}\] %{IPORHOST:[source][address]} %{WORD:[http][request][method]} %{URIPATH:[url][uripath]} HTTP/%{NUMBER:[http][version]} %{INT:[http][response][body][bytes]:int} %{INT:[http][response][status_code]:int} \[%{SYSLOG5424PRINTASCII:[process][name]}\] \[%{NOTSPACE:something1}\] %{NOTSPACE:something2} %{INT:total_time:int}(?<unit>[A-Za-z]+)" } }

  date { match => ["[@metadata][timestamp]",  "dd/MMM/yyyy:HH:mm:ss Z"] 
     #timezone => "Asia/Dubai" 
  }
}

Output:

{
    "something2" => "-",
      "@version" => "1",
           "url" => {
        "uripath" => "/Core/ready-status"
    },
          "http" => {
        "response" => {
                   "body" => {
                "bytes" => 18
            },
            "status_code" => 200
        },
         "version" => "1.1",
         "request" => {
            "method" => "GET"
        }
    },
    "@timestamp" => 2025-02-20T00:01:47.000Z,
    "total_time" => 0,
        "source" => {
        "address" => "10.3.185.541"
    },
          "unit" => "ms",
       "message" => "[20/Feb/2025:00:01:47 +0000] 10.3.185.541 GET /Core/ready-status HTTP/1.1 18 200 [https-jsse-nio-443-exec-16] [-] - 0ms",
    "something1" => "-",
       "process" => {
        "name" => "https-jsse-nio-443-exec-16"
    }
}

Note: Rename fields something1 and something2 or any other field

$ oracle.log

input {
  generator { 
    message => "2025-02-20T15:07:49,058 INFO  [https-jsse-nio-443-exec-4] servlet.ReadyStatusServlet    - doGet call for ReadyStatusServlet. Calling doPost."
    count => 1 } 
}
output {
 stdout {codec => rubydebug{ metadata => true}}
}
filter {
  grok { match => { "message" => "%{TIMESTAMP_ISO8601:[@metadata][timestamp]} %{LOGLEVEL:[log][level]}%{SPACE}\[%{NOTSPACE:[process][name]}\] %{NOTSPACE:method}%{SPACE}-%{SPACE}%{GREEDYDATA:msg}" } }

  date { match => ["[@metadata][timestamp]",  "ISO8601"] 
     timezone => "Asia/Dubai" 
  }

  mutate {  remove_field => [ "event", "host"] }

}

Output:

{
           "msg" => "doGet call for ReadyStatusServlet. Calling doPost.",
       "process" => {
        "name" => "https-jsse-nio-443-exec-4"
    },
    "@timestamp" => 2025-02-20T14:07:49.058Z,
        "method" => "servlet.ReadyStatusServlet",
           "log" => {
        "level" => "INFO"
    },
     "@metadata" => {
        "timestamp" => "2025-02-20T15:07:49,058"
    },
      "@version" => "1",
       "message" => "2025-02-20T15:07:49,058 INFO  [https-jsse-nio-443-exec-4] servlet.ReadyStatusServlet    - doGet call for ReadyStatusServlet. Calling doPost."
}
1 Like

@Rios @elasticforme @leandrojmp Thank you all for your time.

The above solution worked.

@Rios @leandrojmp @elasticforme

Issue still exists. Sharing the screen shot. The problem is why did it pick the event which is older than one day.


timestamp in the below Image is extracted from message.

There is no the lag. You have 2 datetime values, which cause that the first overwrites the second value.
There are options:

  1. have two timestamp fields:
  • @timestamp e.g. type= localhost_access_log
  • @timestamp2 e.g. type= system you can set in the target. You should add in date:
    target => "@timestamp2" # default value is @timestamp
  1. have two pipelines, which means two separated .conf files and of course 2 @timestamp values
1 Like

@Rios Once again thank you for your time in helping me understand.

1 Like

You are welcome.

Long live the King and the Elastic team.

1 Like