Calculate elapsed time without "start" or "end" message

Elastic Stack Logstash
1

Hello,

I have some logs generated by a jobs.
Each job occur have a unique id but there is no specific start message and no specific end message.

I am wondering how can I measured elapsed time between first and last log with a unique id.

I took a look on Elapsed and aggregate plugin but I don't think I can do what I want with those plugins.

Thanks a lot for your help.

Best regards,
Antoine

2

Does the first line in the log constitute a start event that could be used? Does the last line in the log constitute the end event? If so, use those....

It's reasonable that elapsed requires a start and end event in order to work. An example of the log might be helpful.

3

Hello,

Yes, the first line in the log constitute a start. As soon as there is an id in the log it means the beginning of the log.
Please find below some examples:

[2017-06-19 04:40:14,296] [INFO ] [Job: PDF Printing #4240] -- Start update of timed out PDF requests
[2017-06-19 04:40:14,374] [INFO ] [Job: PDF Printing #4240] -- Finish update of timed out PDF requests
[2017-06-19 04:40:14,374] [INFO ] [Job: PDF Printing #4240] -- Start update of PDF services
[2017-06-19 04:40:14,859] [INFO ] [Job: PDF Printing #4240] -- Finish update of PDF services
[2017-06-19 04:40:14,859] [INFO ] [Job: PDF Printing #4240] -- Start deletion of obsolete PDF requests
[2017-06-19 04:40:14,937] [INFO ] [Job: PDF Printing #4240] -- Finish deletion of obsolete PDF requests
[2017-06-19 04:40:14,937] [INFO ] [Job: PDF Printing #4240] -- Refresh PDF Queue, in case we loose some some PDF Requests.
[2017-06-19 04:40:14,937] [INFO ] [Job: PDF Printing #4240] -- Resetting PDFRequest queue.
[2017-06-19 04:40:14,937] [INFO ] [Job: PDF Printing #4240] -- Refresh PDF Queue complete.
[2017-06-19 04:40:14,937] [INFO ] [Job: PDF Printing #4240] -- Flushing changes
[2017-06-19 04:40:14,937] [INFO ] [Job: PDF Printing #4240] -- Saving 10 Nodes as user.
[2017-06-19 04:40:14,984] [INFO ] [Job: PDF Printing #4240] -- Changes flushed.

[2017-06-19 04:40:15,187] [INFO ] [Job: Document Processing #4242] -- Start update of timed out Document Processing requests
[2017-06-19 04:40:15,265] [INFO ] [Job: Document Processing #4242] -- Finish update of timed out Document Processing requests
[2017-06-19 04:40:15,265] [INFO ] [Job: Document Processing #4242] -- Start deletion of obsolete Document Processing requests
[2017-06-19 04:40:15,328] [INFO ] [Job: Document Processing #4242] -- Finish deletion of obsolete Document Processing requests
[2017-06-19 04:40:15,328] [INFO ] [Job: Document Processing #4242] -- Changes flushed.

[2017-06-19 05:05:08,678] [INFO ] [Job: Extract Store QuotationSlicer refresh job #4269] -- Extract Store refresh job monitor progress: 0%.
[2017-06-19 05:05:13,725] [INFO ] [Job: Extract Store QuotationSlicer refresh job #4269] -- Extract Store refresh job monitor progress: 0%.
[2017-06-19 05:05:18,772] [INFO ] [Job: Extract Store QuotationSlicer refresh job #4269] -- Extract Store refresh job monitor progress: 0%.
[2017-06-19 05:05:23,850] [INFO ] [Job: Extract Store QuotationSlicer refresh job #4269] -- Extract Store refresh job monitor progress: 0%.
[2017-06-19 05:24:53,894] [INFO ] [Job: Extract Store QuotationSlicer refresh job #4269] -- Extract Store refresh job monitor progress: 0%.
[2017-06-19 05:24:58,941] [INFO ] [Job: Extract Store QuotationSlicer refresh job #4269] -- Extract Store refresh job monitor progress: 0%.
[2017-06-19 05:25:03,128] [INFO ] [Job: Extract Store QuotationSlicer refresh job #4269] -- Extract Store refresh job monitor progress: 100%.
[2017-06-19 05:25:03,128] [INFO ] [Job: Extract Store QuotationSlicer refresh job #4269] -- Extract Store refresh job progress monitor stopped.
[2017-06-19 05:25:03,206] [INFO ] [Job: Extract Store QuotationSlicer refresh job #4269] -- Changes flushed.

Thanks a lot for your help

4

Can anyone help me on this ?

Thanks

5

Finally I did this in Logstash :

if [profileType] == "Job" {
if "Changes flushed" in [logmessage] {
mutate { add_tag => ["taskEnded"] }
}
else if "" in [idmodule] {
mutate { add_tag => ["taskStarted"] }
}
}
elapsed {
start_tag => "taskStarted"
end_tag => "taskEnded"
timeout => 60
new_event_on_match => false
unique_id_field => "idmodule"
}

Indeed, "idmodule" appears only when a job starts.
I thought it was good like that but sometimes I have "0" in elasped time for job "Extract Store ..", I don't know why.

6

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