topic Re: calculate send response duration in Splunk Search

calculate send response duration

indeed_2000 — Tue, 02 Nov 2021 08:20:31 GMT

I have log like below need to extract "Send&Receive duration" and "send that has not respond".

this is send
2021-07-15 00:00:01,800 INFO CUST.InAB-ServerApp-1234567 [MyService] Packet Processed: A[50] B[0000211]

this is send
2021-07-15 00:00:01,893 INFO ABCD.DaQW-ParityGQQ-1231234 [MyService] Packet Processed: A[60] B[0000465]

this is send

2021-07-15 00:00:01,894 INFO MNBV.ZaQW-ChatCXZ-1478523 [MyService] Packet Processed: A[70] B[0000369]

this is recieve
2021-07-15 00:00:11,719 INFO CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567 [MyService] Normal Packet Received: A[55] B[0000211]

this is recieve
2021-07-15 00:00:11,720 INFO EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234 [MyService] Normal Packet Received: A[65] B[0000456]

here is what happen:

step1: find send id

CUST.InAB-ServerApp-1234567

ABCD.DaQW-ParityGQQ-1231234

MNBV.ZaQW-ChatCXZ-1478523

step2: find response id

CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567

EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234

FYI: related events structure like this:

Send: CUST.InAB-ServerApp-1234567

Recieve: CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567

step3: check this condition A+5 AND B=B to match related send receive.

2021-07-15 00:00:01,800 INFO CUST.InAB-ServerApp-1234567 [MyService] Packet Processed: A[50] B[0000211]

2021-07-15 00:00:11,719 INFO CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567 [MyService] Normal Packet Received: A[55] B[0000211]

step4: finally show id that not have receive, and duration of each send&receive

expected Output:

id status

MNBV.ZaQW-ChatCXZ-1478523 no receive

CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567 9,919

EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234 9,826

Any idea?

Thanks

Re: calculate send response duration

tread_splunk — Tue, 02 Nov 2021 15:29:34 GMT

Most of this is fabricating data.

| makeresults | eval temp="2021-07-15 00:00:01,800 INFO CUST.InAB-ServerApp-1234567 [MyService] Packet Processed: A[50] B[0000211] 2021-07-15 00:00:01,893 INFO ABCD.DaQW-ParityGQQ-1231234 [MyService] Packet Processed: A[60] B[0000465] 2021-07-15 00:00:01,894 INFO MNBV.ZaQW-ChatCXZ-1478523 [MyService] Packet Processed: A[70] B[0000369] 2021-07-15 00:00:11,719 INFO CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567 [MyService] Normal Packet Received: A[55] B[0000211] 2021-07-15 00:00:11,720 INFO EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234 [MyService] Normal Packet Received: A[65] B[0000456] " | makemv tokenizer="(.*)\n" temp | mvexpand temp | rex field=temp "^(?<timestamp>.{23}) INFO (?<customer>.*) \[MyService\] (?<status>.*): (?<Acode>.*) (?<Bcode>.*)" | fields - temp | rex field=customer "_(?<customer2>.*)" | eval customer=coalesce(customer2,customer) | fields - customer2 | eval startTime=if(status="Packet Processed",strptime(timestamp,"%Y-%m-%d %H:%M:%S,%3Q"),null()) | eval endTime=if(status="Normal Packet Received",strptime(timestamp,"%Y-%m-%d %H:%M:%S,%3Q"),null()) | stats values(startTime) as startTime, values(endTime) as endTime by customer | eval status=endTime-startTime | fields - startTime, endTime | fillnull value="no receive" status

Re: calculate send response duration

indeed_2000 — Thu, 04 Nov 2021 12:01:38 GMT

Thanks for answer,

here is the output:

MNBV.ZaQW-ChatCXZ-1478523	9.827000
CUST.InAB-ServerApp-1234567	9.919000
MNBV.ZaQW-ChatCXZ-1478523	no receive

here is the expected output:

MNBV.ZaQW-ChatCXZ-1478523	no receive
CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567	9,919
EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234	9,826

FYI:step3 missed, not check condition.

any idea?

Thanks

Re: calculate send response duration

tread_splunk — Tue, 02 Nov 2021 20:50:46 GMT

@indeed_2000

| makeresults | eval temp="2021-07-15 00:00:01,800 INFO CUST.InAB-ServerApp-1234567 [MyService] Packet Processed: A[50] B[0000211] 2021-07-15 00:00:01,893 INFO ABCD.DaQW-ParityGQQ-1231234 [MyService] Packet Processed: A[60] B[0000465] 2021-07-15 00:00:01,894 INFO MNBV.ZaQW-ChatCXZ-1478523 [MyService] Packet Processed: A[70] B[0000369] 2021-07-15 00:00:11,719 INFO CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567 [MyService] Normal Packet Received: A[55] B[0000211] 2021-07-15 00:00:11,720 INFO EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234 [MyService] Normal Packet Received: A[65] B[0000465] " | makemv tokenizer="(.*)\n" temp | mvexpand temp | rex field=temp "^(?<timestamp>.{23}) INFO (?<customer>.*) \[MyService\] (?<status>.*): A\[(?<Acode>.*)\] B\[(?<Bcode>.*)\]" | fields - temp | rex field=customer "_(?<customer2>.*)" | eval customer2=coalesce(customer2,customer), customer=if(customer=customer2,null(),customer) | eval startTime=if(status="Packet Processed",strptime(timestamp,"%Y-%m-%d %H:%M:%S,%3Q"),null()), endTime=if(status="Normal Packet Received",strptime(timestamp,"%Y-%m-%d %H:%M:%S,%3Q"),null()) | eval AcodeStart=if(status="Packet Processed",Acode,null()),BcodeStart=if(status="Packet Processed",Bcode,null()),AcodeFinish=if(status="Normal Packet Received",Acode,null()),BcodeFinish=if(status="Normal Packet Received",Bcode,null()) | fields - Acode Bcode _time timestamp status | stats values(*) as * by customer2 | eval status=endTime-startTime , customer=coalesce(customer,customer2) | fields - startTime, endTime | fillnull value="no receive" status | where isnull(AcodeFinish) OR (AcodeFinish=AcodeStart+5 AND BcodeStart=BcodeFinish) | table customer status

Re: calculate send response duration

indeed_2000 — Thu, 04 Nov 2021 12:00:45 GMT

I try it on small part of log it work perfect but on a large scale I have issue.

here is the line that cause of issue:

actually duration between green lines show on table.

red lines show there is no "receive", because not have second line with condition that I mention A=A+5 AND B=B

---------------------------------------

this is recieve
2021-07-15 00:00:01,800 INFO CUST.InAB-ServerApp-1234567 [MyService] Normal Packet Received: A[50] B[0000211]

this is send

2021-07-15 00:00:01,800 INFO CUST.InAB-ServerApp-1234567 [MyService] Packet Processed: A[50] B[0000211]

this is recieve
2021-07-15 00:00:11,719 INFO CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567 [MyService] Normal Packet Received: A[55] B[0000211]

this is send
2021-07-15 00:00:11,719 INFO CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567 [MyService] Packet Processed: A[55] B[0000211]

----------------------------------------

this is recieve

2021-07-15 00:00:01,894 INFO MNBV.ZaQW-ChatCXZ-1478523 [MyService] Normal Packet Received: A[70] B[0000369]

this is send

2021-07-15 00:00:01,894 INFO MNBV.ZaQW-ChatCXZ-1478523 [MyService] Packet Processed: A[70] B[0000369]

----------------------------------------

this is recieve
2021-07-15 00:00:01,893 INFO ABCD.DaQW-ParityGQQ-1231234 [MyService] Normal Packet Received: A[60] B[0000465]

this is send
2021-07-15 00:00:01,893 INFO ABCD.DaQW-ParityGQQ-1231234 [MyService] Packet Processed: A[60] B[0000465]

this is recieve

2021-07-15 00:00:11,720 INFO EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234 [MyService] Normal Packet Received: A[65] B[0000465]

this is send

2021-07-15 00:00:11,720 INFO EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234 [MyService] Packet Processed: A[65] B[0000465]

here is the expected output:

MNBV.ZaQW-ChatCXZ-1478523	no receive
CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567	9,919
EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234	9,826

Any idea?

Thanks

Re: calculate send response duration

tread_splunk — Wed, 03 Nov 2021 13:47:00 GMT

@indeed_2000

Your second green pair have different B codes. 465 vs 456. This is a typo, correct?

Re: calculate send response duration

indeed_2000 — Wed, 03 Nov 2021 13:52:19 GMT

you right, it is a typo, I've edit it.

Re: calculate send response duration

tread_splunk — Thu, 04 Nov 2021 09:38:45 GMT

@indeed_2000

Why is ...

ABCD.DaQW-ParityGQQ-1231234

no receive

...in the output?

Re: calculate send response duration

indeed_2000 — Thu, 04 Nov 2021 09:59:32 GMT

For more clarification Here is flow:

1-receive request from a source

2-processed request and send to another node

3-receive response from that node

4-send response to source

Need to extract duration between step 2 and 3

sometimes node doesn’t send response, then step 3,4 missed and flow is incomplete.

FYI: you may confused with step 1,2 or 3,4 (send and receive) keyword, but in simple way 1,2 means request received and send to node. 3,4 means receive response and send to source.

any idea?

Thanks

Re: calculate send response duration

tread_splunk — Thu, 04 Nov 2021 11:20:04 GMT

@indeed_2000

Still not sure why...

ABCD.DaQW-ParityGQQ-1231234

no receive

...is in the result. Shouldn't it be the red one? i.e...

2021-07-15 00:00:01,894 INFO MNBV.ZaQW-ChatCXZ-1478523 [MyService] Packet Processed: A[70] B[0000369]

Re: calculate send response duration

indeed_2000 — Thu, 04 Nov 2021 11:59:54 GMT

Sorry it’s typo, modify that too.

Re: calculate send response duration

tread_splunk — Thu, 04 Nov 2021 13:46:30 GMT

@indeed_2000

Its not very pretty. And requires extensive testing.

| makeresults | eval temp="2021-07-15 00:00:01,800 INFO CUST.InAB-ServerApp-1234567 [MyService] Normal Packet Received: A[50] B[0000211] 2021-07-15 00:00:01,800 INFO CUST.InAB-ServerApp-1234567 [MyService] Packet Processed: A[50] B[0000211] 2021-07-15 00:00:11,719 INFO CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567 [MyService] Normal Packet Received: A[55] B[0000211] 2021-07-15 00:00:11,719 INFO CUST.VqPO-Oracle7-9876543_CUST.InAB-ServerApp-1234567 [MyService] Packet Processed: A[55] B[0000211] 2021-07-15 00:00:01,894 INFO MNBV.ZaQW-ChatCXZ-1478523 [MyService] Normal Packet Received: A[70] B[0000369] 2021-07-15 00:00:01,894 INFO MNBV.ZaQW-ChatCXZ-1478523 [MyService] Packet Processed: A[70] B[0000369] 2021-07-15 00:00:01,893 INFO ABCD.DaQW-ParityGQQ-1231234 [MyService] Normal Packet Received: A[60] B[0000465] 2021-07-15 00:00:01,893 INFO ABCD.DaQW-ParityGQQ-1231234 [MyService] Packet Processed: A[60] B[0000456] 2021-07-15 00:00:11,720 INFO EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234 [MyService] Normal Packet Received: A[65] B[0000456] 2021-07-15 00:00:11,720 INFO EFGH.GaXZ-Carry2-3456789_ABCD.DaQW-ParityGQQ-1231234 [MyService] Packet Processed: A[65] B[0000456] " | makemv tokenizer="(.*)\n" temp | mvexpand temp | rex field=temp "^(?<timestamp>.{23}) INFO (?<customer>.*) \[MyService\] (?<status>.*): A\[(?<Acode>.*)\] B\[(?<Bcode>.*)\]" | fields - temp | rex field=customer "_(?<customer2>.*)" | eval customer2=coalesce(customer2,customer), customer=if(customer=customer2,null(),customer) | eval sendTime=if(status="Packet Processed",strptime(timestamp,"%Y-%m-%d %H:%M:%S,%3Q"),null()), receiveTime=if(status="Normal Packet Received",strptime(timestamp,"%Y-%m-%d %H:%M:%S,%3Q"),null()) | eval AcodeSend=if(status="Packet Processed",Acode,null()),BcodeSend=if(status="Packet Processed",Bcode,null()),AcodeReceive=if(status="Normal Packet Received",Acode,null()),BcodeReceive=if(status="Normal Packet Received",Bcode,null()) | eval AcodeReceiveLookFor=AcodeSend+5,acr=coalesce(AcodeReceive,AcodeReceiveLookFor) | fields - Acode _time timestamp status AcodeReceiveLookFor | stats values(*) as *,count by customer2,acr,Bcode | eval duration=receiveTime-sendTime , customer=coalesce(customer,customer2) | eval status=case(isnull(AcodeSend),"No Send",isnull(AcodeReceive),"No receive") | eventstats max(duration) as duration by customer2 | where count=2 OR (status="No receive" AND isnull(duration)) | eval status=coalesce(status,duration) | table customer status