Logstash Elapsed filter not working

[nakula (Naga)]

I am trying to find the different between the start time and end time of a transaction.
I am using the sample log file as below..

2022-07-17T12:36:30.3081415Z Info 38 [xxx.frame.logging.serviceCols] ["Level3"] : Wires-301 : Start id : 897agsh: WiresActor created for 301
2022-07-17T12:38:30.3081415Z Info 38 [xxx.frame.logging.serviceCols] ["Level3"] : Wires-301 : 301started : did something 301
2022-07-17T12:39:30.3081415Z Info 38 [xxx.frame.logging.serviceCols] ["Level3"] : Wires-301 : 301started : logged something 301
2022-07-17T12:40:30.3081415Z Info 38 [xxx.frame.logging.serviceCols] ["Level3"] : Wires-301 : 301started : parked in to sideway 301
2022-07-17T12:42:30.3081415Z Info 38 [xxx.frame.logging.serviceCols] ["Level3"] : Wires-301 : 301started : blocked for sometime 301
2022-07-17T12:44:30.3081415Z Info 38 [xxx.frame.logging.serviceCols] ["Level3"] : Wires-301 : End id : 897agsh : aslkjalksjlkjas 301

My intention is to read this log and find the difference of the timestamps. Bolded are the Unique Ids for this sample transaction.

My config file looks as below:

input {
file {
path => "C:/tools/logstash-8.3.1/config/logs/vv.log"
start_position => beginning
sincedb_path => "C:/tools/logstash-8.3.1/config/logs/level_sincedb"
}
}
filter {
grok {
match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} %{DATA:loglevel} %{DATA:codeline} [%{DATA:framework}.<>c] ["%{DATA:level}"] : %{DATA:symbot} : Start id : %{DATA:id} :" }
add_tag => "transactionstarted"
}
grok {
match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} %{DATA:loglevel} %{DATA:codeline} [%{DATA:framework}] ["%{DATA:level}"] : %{DATA:wire} : End id : %{DATA:id}:" }
add_tag => "transactionended"
}
elapsed {
start_tag => "transactionstarted"
end_tag => "transactionended"
unique_id_field => "id"
new_event_on_match => true
}
date {
match => [ "timestamp", ISO8601 ]
}
}
output {
elasticsearch { hosts => ["localhost:9200"] }
stdout { codec => rubydebug }
}

I can see the logs in the Kibana but not seeing the elapsed.Time or any other elapsed related fields.

Am I missing something here?

[nakula (Naga)]

By the way, the output looks as below:

[Badger]

You very likely want the date filter before the elapsed filter.

[Rios]

@nakula

filter {
grok {
match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} %{DATA:loglevel} %{DATA:codeline} [%{DATA:framework}.<>c] ["%{DATA:level}"] : %{DATA:symbot} : Start id : %{DATA:id} :" }
add_tag => "transactionstarted"
}
grok {
match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} %{DATA:loglevel} %{DATA:codeline} [%{DATA:framework}] ["%{DATA:level}"] : %{DATA:wire} : End id : %{DATA:id}:" }
add_tag => "transactionended"
}

Groks are not ok, should be:

grok {
match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} %{DATA:loglevel} %{DATA:codeline} \[%{DATA:framework}\] \["%{DATA:level}"\] : %{DATA:symbot} : Start id : %{DATA:id}: %{GREEDYDATA:info}" }
add_tag => "transactionstarted"
}
grok {
match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} %{DATA:loglevel} %{DATA:codeline} \[%{DATA:framework}\] \["%{DATA:level}"\] : %{DATA:wire} : End id : %{DATA:id} : %{GREEDYDATA:info}" }
add_tag => "transactionended"
}

[nakula (Naga)]

Yes, I have corrected the grok filter and I am not seeing any grok parse errors.

With elapsed filter, I am expecting to see the time difference between 2 log lines (which make a transaction with a unique id), but I am not seeing the elapsed time.

It shows a tag "elapsed_end_without_start" for the transactionended log.

Why am I not seeing elapsed time even if the two log lines are more than 10 seconds apart?

[nakula (Naga)]

Yes, I have moved it.

[Badger]

@nakula

new_event_on_match => true

The elapsed time is not added to the end event, a new event is created that contains the start timestamp, the id, the elapsed time, and the tags "elapsed" and "elapsed_match".

[nakula (Naga)]

hi badger,
where can I see that new event?
How do I search for it?

[Badger]

Search for an event with the tag "elapsed_match".