Calculate time difference between two log lines - Logstash

[giancringo (Gianmarco)]

Hello,
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?

[AquaX (Andreas Helmer)]

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.

[AquaX (Andreas Helmer)]

Can you post your logstash config including the elapsed config?

[giancringo (Gianmarco)]

@AquaX

NOTSPACE"

Hi,
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 } }

[AquaX (Andreas Helmer)]

@giancringo

        add_field => { "[@metadata][ts]" => "%{date} %{hour}" }
   }
date { match => [ "[@metadata][ts]", "ISO8601" ] }

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" ] }