Get time difference between events

[siddharthmis]

Hi,

I have events like following (in the sequence of occurrence)-

{"TransactionId":"570978b406264e398d888cd8b49f867d","ParentId":"","RequestId":"24529c4700e942e1ba036f87b0d6080e","Customer":"86c62bf7f6ee4a1ab004e7e33ad9068a","Action":"ExecuteWCFTask/TestRun","Start":"2018-02-05T08:08:42.4689427+00:00","End":"2018-02-05T08:08:42.9378465+00:00","RequestType":3}

{"TransactionId":"570978b406264e398d888cd8b49f867d","ParentId":"24529c4700e942e1ba036f87b0d6080e","RequestId":"c0114983065a45fb83efa433f093ce06","Customer":"86c62bf7f6ee4a1ab004e7e33ad9068a","Action":"ExecuteWCFTaskService/StartTask","Start":"2018-02-05T08:08:42.48456+00:00","End":"2018-02-05T08:08:42.5158124+00:00","RequestType":5}

{"TransactionId":"570978b406264e398d888cd8b49f867d","ParentId":"c0114983065a45fb83efa433f093ce06","RequestId":"0d1438b1e8af4021a7848314f9e88daf","Customer":"86c62bf7f6ee4a1ab004e7e33ad9068a","Action":"TestRun","Start":"2018-02-05T08:08:42.634785+00:00","End":"2018-02-05T09:54:19.5054132+00:00","RequestType":16}

{"TransactionId":"570978b406264e398d888cd8b49f867d","ParentId":"0d1438b1e8af4021a7848314f9e88daf","RequestId":"bb95c271d2ef412d89bebe74f5db4aff","Customer":"86c62bf7f6ee4a1ab004e7e33ad9068a","Action":"UpdateTaskExecutionHistory","Start":"2018-02-05T09:54:48.2226293+00:00","End":"2018-02-05T09:54:48.2382566+00:00","RequestType":5}

The sequence is always the same, i.e. first we have request type 3, then 5, then 16 and then 5.
Request ID of the first event is the parent ID of second.

The Only parameter common in all events in the TransactionId.

In the above example, Event with RequestType 16 was logged almost 106 minutes after event with RequestType 5 was logged.

I need the Customer and Action from the events whose requestType 16 is not received in real-time.

For e.g. If event with request type 5 is logged at 0500 UTC and search is run at 0700 UTC, I would like to get the customer and action of the event whose requestType 16 is still not logged.

I tried something like-

sourcetype=test  TransactionId=* RequestType=3 | eval epocs=strptime(Start, "%Y-%m-%dT%H:%M:%S.%f") | eval epoce=strptime(End, "%Y-%m-%dT%H:%M:%S.%f")  | stats max(_time) as last_time by Customer, TransactionId | eval latency_minutes=((now()-last_time)/60) | convert ctime(last_time) as last_time | fields + Customer, TransactionId, last_time, latency_minutes

But it didn't help.

[somesoni2]

Give this a try

sourcetype=test  TransactionId=* RequestType=3 OR RequestType=5 OR RequestType=16
| stats list(RequestType) as RequestTypes values(Customer) as Customer values(Action) as Action max(_time) as last_time by TransactionId
| where isnull(mvfind(RequestTypes,"16"))
| eval latency_minutes=((now()-last_time)/60) | convert ctime(last_time) as last_time
| fields - RequestTypes

[siddharthmis]

@somesoni2 I tried:

 sourcetype=test  TransactionId=* RequestType=3
 | stats list(RequestType) as RequestTypes values(Customer) as Customer values(Action) as Action max(_time) as last_time by TransactionId
 | where isnull(mvfind(RequestTypes,"16"))
 | eval latency_minutes=((now()-last_time)/60) | convert ctime(last_time) as last_time
 | fields - RequestTypes

It gives the results alongwith many other incorrect rows, reason being for some tranasctions, the order of the RequestType is 16,3,5,5 and 3,16,5,5

I believe we will need to check if for a transaction, we have action "UpdateTaskExecutionHistory" written or not

[siddharthmis]

@somesoni2, maybe something like -

sourcetype=_json source="http:alusta_etw"  Instance=UK4 Action="*ANYERP*" TransactionId=*  RequestType=3 OR RequestType=5 OR RequestType=16   | stats list(RequestType) as RequestTypes values(TenantCode) as TenantCode list(Action) as Actions max(_time) as last_time by TransactionId  | where isnull(mvfind(Actions,"SchedulerTaskHistoryUpdateGatewayService/UpdateTaskExecutionHistory")) | eval latency_minutes=((now()-last_time)/60) | convert ctime(last_time) as last_time  | fields - RequestTypes

[siddharthmis]

@somesoni2, can you help me out here?

[cmerriman]

do you basically need to know at the time of your search if all four events have been logged for every transaction? If that's the case, you could just do sourcetype=test TransactionId=*|transaction TransactionId maxspan=1h maxpause=10m|where eventcount<4, if needed you could continue with your
|stats max(_time) as latest_time by Customer, TransactionId.... but this should get you any transaction that didn't reach all four events.
you can also adjust the maxspan/maxpause in the transaction command to suit your needs. There are other arguments available, as well.
https://docs.splunk.com/Documentation/Splunk/7.0.2/SearchReference/Transaction

[siddharthmis]

I think it would be good if we can get the transaction details whose RequestType 3 is logged but RequestType 16 is not and the latency minutes.

basically I am looking for long running transactions, RequestType 16 is logged after the transaction is complete, so I have to rely on RequestType 3 for the details.

[siddharthmis]

Any ideas Anyone?

[siddharthmis]

I ran-

sourcetype=test TransactionId=* |transaction TransactionId maxspan=-1 maxpause=-1 | where (eventcount<3 and eventcount>1)  | stats max(_time) as last_time by Customer, TransactionId | eval latency_minutes=((now()-last_time)/60) | convert ctime(last_time) as last_time | fields + Customer, TransactionId, last_time, latency_minutes

It gave my what I need but a lot of incorrect rows-

It returned the TransactionId - 309fe4177f9f41ba9141de2d1fed71a7 for which raw events were:

{"TransactionId":"309fe4177f9f41ba9141de2d1fed71a7","ParentId":"","RequestId":"941a38abcfe24a64b83417d76b8ce08d","Customer":"Dummy","Action":"ExecuteWCFTask/Check","Start":"2018-02-08T02:07:35.0661083+00:00","End":"2018-02-08T02:07:35.2067272+00:00","RequestType":3}

{"TransactionId":"309fe4177f9f41ba9141de2d1fed71a7","ParentId":"941a38abcfe24a64b83417d76b8ce08d","RequestId":"8bd669290510421faa744def84043357","Customer":"Dummy","Action":"ExecuteWCFTaskService/StartTask","End":"2018-02-08T02:07:35.2067272+00:00","RequestType":5}

{"TransactionId":"309fe4177f9f41ba9141de2d1fed71a7","ParentId":"8bd669290510421faa744def84043357","RequestId":"f03d9c78-6223-4ffe-9e26-76e0ea81b029","Customer":"Dummy","Action":"Check","Start":"2018-02-08T02:07:51.9417927+00:00","End":"2018-02-08T03:40:53.6402105+00:00","RequestType":16}

{"TransactionId":"309fe4177f9f41ba9141de2d1fed71a7","ParentId":"2f15f976e3d54fa6b91872a32c0f60d0","RequestId":"26f038288d2f46a7b88772a9b1402ec3","Customer":"Dummy","Action":"UpdateTaskExecutionHistory","Start":"2018-02-08T03:41:09.4014092+00:00","End":"2018-02-08T03:41:09.4170427+00:00","RequestType":5}

[siddharthmis]

I think one possible way to find what I am looking for is to get the transactionID of the event with requestType 5 whose requestId is not the parentId of any event.

[siddharthmis]

Can anyone please suggest what can be done?