find time gaps

[indeed_2000]

Hi i have log like this, need to find where unusuall time gap between "Packet Processed" and "Send Packet" that exist

this is normal 001
2021-10-25 08:59:50,725 INFO CUS.AbCD-VW2-1234567890 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:50,726 INFO CUS.AbCD-VW2-1234567890 [AppClientManager] Send Packet

this is normal 035
2021-10-25 08:59:52,730 INFO CUS.AbCD-VW2-0987654321 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:52,735 INFO CUS.AbCD-VW2-0987654321 [AppClientManager] Send Packet

this is NOT normal 5:230
2021-10-25 08:59:54,725 INFO CUS.AbCD-VW2-1478523699 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:59,955 INFO CUS.AbCD-VW2-1478523699 [AppClientManager] Send Packet

this is NOT normal 1:100
2021-10-25 08:59:58,705 INFO CUS.AbCD-VW2-9632587411 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:59,805 INFO CUS.AbCD-VW2-9632587411 [AppClientManager] Send Packet

this is NOT normal 100
2021-10-25 08:59:59,800 INFO CUS.AbCD-VW2-3333322222 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:59,950 INFO CUS.AbCD-VW2-3333322222 [AppClientManager] Send Packet

this is huge log and imagine lot's of line like this write to log file without order as i sort above need to know when count of unusuall time gaps increase.

2021-10-25 08:59:50,725 INFO CUS.AbCD-VW2-1234567890 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:50,726 INFO CUS.AbCD-VW2-1234567890 [AppClientManager] Send Packet
2021-10-25 08:59:52,730 INFO CUS.AbCD-VW2-0987654321 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:52,735 INFO CUS.AbCD-VW2-0987654321 [AppClientManager] Send Packet
2021-10-25 08:59:54,725 INFO CUS.AbCD-VW2-1478523699 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:58,705 INFO CUS.AbCD-VW2-9632587411 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:59,800 INFO CUS.AbCD-VW2-3333322222 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:59,805 INFO CUS.AbCD-VW2-9632587411 [AppClientManager] Send Packet
2021-10-25 08:59:59,950 INFO CUS.AbCD-VW2-3333322222 [AppClientManager] Send Packet
2021-10-25 08:59:59,955 INFO CUS.AbCD-VW2-1478523699 [AppClientManager] Send Packet

FYI: unusuall time gaps means increase time between "Packet Processed" & "Send Packet"

Any idea?

Thanks,

[ITWhisperer]

| makeresults
| eval _raw="2021-10-25 08:59:50,725 INFO CUS.AbCD-VW2-1234567890 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:50,726 INFO CUS.AbCD-VW2-1234567890 [AppClientManager] Send Packet
2021-10-25 08:59:52,730 INFO CUS.AbCD-VW2-0987654321 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:52,735 INFO CUS.AbCD-VW2-0987654321 [AppClientManager] Send Packet
2021-10-25 08:59:54,725 INFO CUS.AbCD-VW2-1478523699 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:58,705 INFO CUS.AbCD-VW2-9632587411 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:59,800 INFO CUS.AbCD-VW2-3333322222 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:59,805 INFO CUS.AbCD-VW2-9632587411 [AppClientManager] Send Packet
2021-10-25 08:59:59,950 INFO CUS.AbCD-VW2-3333322222 [AppClientManager] Send Packet
2021-10-25 08:59:59,955 INFO CUS.AbCD-VW2-1478523699 [AppClientManager] Send Packet"
| multikv noheader=t



| rex "(?<time>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2},\d{3})\sINFO\s(?<txid>[\S]+)\s\[[^\]]+\]\s.*(?<event>(Processed|Send))"
| eval _time=strptime(time,"%Y-%m-%d %H:%M:%S,%Q")
| eval {event}=_time
| stats values(Processed) as Processed values(Send) as Send by txid
| eval gap=Send-Processed

[indeed_2000]

Thank you for answer,

actually the main issue is find patterns like this:

2021-10-25 08:59:50,725 INFO CUS.AbCD-VW2-1234567890 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:50,726 INFO CUS.AbCD-VW2-1234567890 [AppClientManager] Send Packet
2021-10-25 08:59:52,730 INFO CUS.AbCD-VW2-0987654321 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:52,735 INFO CUS.AbCD-VW2-0987654321 [AppClientManager] Send Packet

2021-10-25 08:59:54,736 INFO CUS.AbCD-VW2-6478523699 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:54,736 INFO CUS.AbCD-VW2-6632587411 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:54,737 INFO CUS.AbCD-VW2-6333322222 [FlowProcessorService] Packet Processed:

2021-10-25 08:59:54,725 INFO CUS.AbCD-VW2-1478523699 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:58,705 INFO CUS.AbCD-VW2-9632587411 [FlowProcessorService] Packet Processed:

2021-10-25 08:59:59,800 INFO CUS.AbCD-VW2-3333322222 [FlowProcessorService] Packet Processed:
2021-10-25 08:59:59,805 INFO CUS.AbCD-VW2-9632587411 [AppClientManager] Send Packet
2021-10-25 08:59:59,950 INFO CUS.AbCD-VW2-3333322222 [AppClientManager] Send Packet
2021-10-25 08:59:59,955 INFO CUS.AbCD-VW2-1478523699 [AppClientManager] Send Packet

2021-10-25 09:00:00,956 INFO CUS.AbCD-VW2-6632587411 [AppClientManager] Send Packet
2021-10-25 09:00:00,956 INFO CUS.AbCD-VW2-6333322222 [AppClientManager] Send Packet
2021-10-25 09:00:00,956 INFO CUS.AbCD-VW2-6478523699 [AppClientManager] Send Packet

sometimes lots of Packet Processed come and related Send Packet stuck in queue, need to find them.

here is the flow:

1-(Packet Processed) node1send packet to node2 >  

2-node2 (return response to node1) >

3-(Send Packet) node1 send packet to another node 3

as you see couple of times continuously (Packet Processed).

Its duration varies, actually this is a pattern or behavior.

is there any way to do this with splunk?

Thanks,

[ITWhisperer]

I am not sure what you think is a pattern - the example I showed will allow you to determine the "time gaps" between packet processed and send packet messages for each transaction id (I am assuming that this is what the string beginning CUS is). You can then identify which of these are over your expected gap. Is this not what you are looking for?

[indeed_2000]

Actually i think about Splunk Machine Learning Toolkit (MLTK) or outliner or density function may help us to detect these abnormal conditions. 

as I mentioned only extract duration not solve issue. 
FYI: sometimes might the duration is high for some Proceed & Send and its normal, but when couple of Proceed come and queued after a while Send appear this means something wrong,in this condition duration might be high or low. 
so high duration not resolve issue here.

Another idea is measure density of “Proceed” over the time due to “Send”.

any other idea?

 Thanks