The key is docKey for each of the three records. I need the start time from log having action=UPLOAD and end time from log having action=NOTIFY. Once we get the two times , we have to subtract the two times to get the total time taken for the process from begin process to end.
The logs are:
<06-05-2018 04:53:46 PM EDT> < INFO> [DefaultMessageListenerContainer-14] AspectLogging:39 - [action=NOTIFY, DOCTYPE=INVOICE_PDF, status=C, docKey=814742506620_052718_45527429.pdf, startTime=2018-06-05 16:53:46.396 EDT, endTime=2018-06-05 16:53:46.409 EDT, totalTime=13]
host = rtlvpsaw02.labcorp.com CFP source = /opt/ibm/logs/applogs/cfpds-invoice-rpt-ecs-upload-srvc.log sourcetype = DS-InvRpt-log
<06-05-2018 04:53:46 PM EDT> < INFO> [DefaultMessageListenerContainer-14] AspectLogging:39 - [action=LPID, DOCTYPE=INVOICE_PDF, status=C, docKey=814742506620_052718_45527429.pdf, lpid=9291437470834759, accountNumber=29032270, requestTime=2018-06-05 16:53:46.397 EDT, responseTime=10]
host = rtlvpsaw02.labcorp.com CFP source = /opt/ibm/logs/applogs/cfpds-invoice-rpt-ecs-upload-srvc.log sourcetype = DS-InvRpt-log
<06-05-2018 04:53:46 PM EDT> < INFO> [DefaultMessageListenerContainer-4] AspectLogging:39 - [action=UPLOAD, DOCTYPE=INVOICE_PDF, status=C, docKey=814742506620_052718_45527429.pdf, uploadStartTime=1528232025750, uploadTime=638, startTime=2018-06-05 16:53:45.750 EDT, endTime=2018-06-05 16:53:46.394 EDT, totalTime=644]
host = rtlvpsaw01.labcorp.com CFP source = /opt/ibm/logs/applogs/cfpds-invoice-rpt-ecs-upload-srvc.log sourcetype = DS-InvRpt-log
Since you want the startTime
of the first event and the endTime
of the last event, this is the way I would do it:
<YOUR_BASE_SEARCH>
| transaction docKey
| stats min(startTime) as start, max(endTime) as end
| eval d=strptime(end, "%F %T.%N %Z")-strptime(start, "%F %T.%N %Z")
I tried it using your data, and the answer that resulted was 0.659000
. It just combines all of the events with the same docKey
. Your example data is in the reverse order that I would have expected, so I'm not sure if that was intentional or not, so I didn't account for multiple potential UPLOAD and NOTIFY events for the same docKey
. If the events are in the opposite order that they really would come in, then you could add startswith=UPLOAD
to the transaction
command in order to separate the sets of events at the transaction level.
How about this?
index=foo sourcetype=bar (action=UPLOAD OR action=NOTIFY) | stats values(action) as actions range(_time) as duration by docKey | search action=UPLOAD action=NOTIFY
That will get you all docKey values that have both UPLOAD and NOTIFY events, and compute the time span between the first and last event as the duration.