Elapsed time filter - not matching first event!

Elastic Stack Logstash
1

Hi there,

I've searched the forum but it seems to be such a fundamental part of the elapsed time filter that no one else seems to have had the problem, but..... has the keep_start_event tag in this filter ever not been obeyed for anyone?

I have a situation whereby my request trail has multiple start events (all with the same unique id) but when the eventual end event is found, the elapsed time is being worked out as the last time the start_event was seen, not the first! The default is that it takes the first, correct?

My config is as below:

        if [blah.message] == "Booked" {
            mutate {
                add_tag => ["journeyEnded"]
            }
        } else if [blah.operationName] == "GetProduct" {
              mutate {
                  add_tag => ["journeyStarted"]
             }
        }

        elapsed {
            start_tag => "journeyStarted"
            end_tag => "journeyEnded"
            unique_id_field => "trace"
            timeout => 2700
            new_event_on_match => false
        }

A list of my requests are as below

{
   "timestamp":"2018-09-28T13:53:45.006+01:00",
   "level":"INFO",
   "service":"product",
   "trace":"00000000374f3f41",
   "span":"000000000f675b75",
   "blah.operationName":"GetProduct",
   "blah.value":"",
   "blah.serviceMetric":"",
   "blah.geoarea":"",
   "blah.authcode":"",
   "blah.pupilId":"",
   "blah.lessonDateTime":"",
   "blah.exceptionMessage":"",
   "blah.message":"Operation started for: GetProduct"
}

tags OPP-VM, beats_input_codec_plain_applied, journeyStarted

{
   "timestamp":"2018-09-28T14:00:31.874+01:00",
   "level":"INFO",
   "service":"product",
   "trace":"00000000374f3f41",
   "span":"6725ef0be7d66586",
   "blah.operationName":"GetProduct",
   "blah.value":"",
   "blah.serviceMetric":"",
   "blah.geoarea":"",
   "blah.authcode":"",
   "blah.pupilId":"",
   "blah.lessonDateTime":"",
   "blah.exceptionMessage":"",
   "blah.message":"Operation started for: GetProduct"
}

tags OPP-VM, beats_input_codec_plain_applied, journeyStarted

    {
       "timestamp":"2018-09-28T14:01:54.882+01:00",
       "level":"INFO",
       "service":"product",
       "trace":"00000000374f3f41",
       "span":"ea0750a098f45aa7",
       "blah.operationName":"GetProduct",
       "blah.value":"",
       "blah.serviceMetric":"",
       "blah.geoarea":"",
       "blah.authcode":"",
       "blah.pupilId":"",
       "blah.lessonDateTime":"",
       "blah.exceptionMessage":"",
       "blah.message":"Operation started for: GetProduct"
    }

tags OPP-VM, beats_input_codec_plain_applied, journeyStarted

{
   "timestamp":"2018-09-28T14:01:56.317+01:00",
   "level":"INFO",
   "service":"booking",
   "trace":"00000000374f3f41",
   "span":"00000000006df1fa",
   "blah.operationName":"",
   "blah.value":"1001",
   "blah.serviceMetric":"Booked",
   "blah.geoarea":"",
   "blah.authcode":"",
   "blah.pupilId":"",
   "blah.lessonDateTime":"",
   "blah.exceptionMessage":"",
   "blah.message":"Booked"
}

tags OPP-VM, beats_input_codec_plain_applied, journeyEnded, elapsed, elapsed_match

elapsed_timestamp_start September 28th 2018, 14:01:54.882

elapsed_time 1.435

(Using version 6.4 of Logstash)

2

Just me then? :confused:

3

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