Calculate time difference between two log lines - Logstash

I'm looking for a solution to calculate the difference between two time on two different log lines as below:

2020-06-11 15:31:22,817 [http-8080-0] INFO  it.example.sign.sign.SignTool  - [TYPE] trackingID: x12e65r7-0uggr56-jhgdxc-oij78hf5-12345rtyu @ 15:31:22.817000000, progress method opensession
2020-06-11 15:31:23,817 [http-8080-0] INFO  it.example.sign.sign.SignTool  - [TYPE] trackingID: x12e65r7-0uggr56-jhgdxc-oij78hf5-12345rtyu @ 15:31:23.617000000, completed method opensession

This is my grok filter that match the log lines:

%{DATE_EU:date} %{TIME:hour} \[%{GREEDYDATA:protocol_port}\] %{LOGLEVEL:log-level} %{GREEDYDATA:message} ( )?- (\[%{GREEDYDATA:type}\] )?trackingID: %{DATA:trackingID} @ %{TIME:method_time}, %{DATA:method_state} %{GREEDYDATA:message} %{USER:method_type}

I tried to match the time with the date filter and to use the elapsed filter but it didn't work.

Are there any solution to achieve my goal using elapsed or a ruby script?

Elapsed is the right filter to use for this...however there has to be a field that is unique and common to the thread in order for that to work properly (ie a thread or process number) plus you need to be able to define the start and stop.

Also, I would recommend changing "GREEDYDATA" to something more specific as GREEDYDATA is quite resource intensive. Use "NOTSPACE" or "DATA" if you can.

Can you post your logstash config including the elapsed config?

thank you for the answer and for the advice.

Here my logstash config file:

input {
  file {
   path => "/home/elastic/grok_test/one_line.log"
   start_position => "beginning"
   sincedb_path => "/dev/null"
filter {
   grok {
        match => ["message", "%{DATE_EU:date} %{TIME:hour} \[%{GREEDYDATA:protocol_port}\] %{LOGLEVEL:log-level} %{GREEDYDATA:message} ( )?- (\[%{GREEDYDATA:type}\] )?trackingID: %{DATA:trackingID} @ %{TIME:method_time}, %{DATA:method_state} %{GREEDYDATA:message} %{USER:method_type}"]
        add_tag => [ "%{method_state}" ]
        add_field => { "[@metadata][ts]" => "%{date} %{hour}" }
date { match => [ "[@metadata][ts]", "ISO8601" ] }
elapsed {
    unique_id_field => "trackingID"
    start_tag => "progress"
    end_tag => "completed"
    add_tag => ["time_elapsed"]
  if "time_elapsed" in [tags] {
        ruby { code => 'event.set("elapsed_time_ms", 1000.0 * event.get("elapsed_time"))' }
output { stdout { codec => rubydebug } }

I'm pretty sure this is your problem

Going from your example
%{date} %{hour} would evaluate to: 20-06-11 15:31:23,817 which is NOT ISO8601 format.
Change your date filter to: date { match => [ "[@metadata][ts]", "yy-MM-dd HH:mm:ss,SSS" ] }

1 Like

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