topic Re: Correlating Different Events and Calculating Time Difference in Splunk Search

Correlating Different Events and Calculating Time Difference

dw385 — Fri, 18 Mar 2016 19:10:24 GMT

I’m trying to report on the time difference between two related events. Both events are collected from Windows event log and are in the same index. They will occur on the same host but at different times and IDs.
Example event data:

Time: 3/11/2016 9:00:45 PM
EventID: 1000
Source: Backup Agent Message:
Backup Started
Host: Server1
Time: 3/12/2016 1:09:45 AM

EventID: 1001
Source: Backup Agent
Message: Backup Completed
Host: Server1

The second event can occur any time after the first, maybe in a few minutes or a few hours. I’m thinking I need to find event 1(1000) first and then look for the first occurrence of event 2 afterwards. The index would contain similar events from many hosts around the same time.
I’ve tried various attempts with joins, transactions, and subsearches and searching the documentation for suggestions with no luck. I’m really not concerned with any of the data in the event other than the time (which I would eval to a start and end time). The goal is to be able to run a report over a time span to show the start/end times for each host.

This gets me close but doesn’t scale to multiple hosts/time ranges:

index="wineventlog" SourceName="Backup Agent" (EventCode="1000" OR EventCode="1001") 
| transaction maxspan=4h startswith=(EventCode="1000") endswith=(EventCode="1001") 
| table host,duration

Re: Correlating Different Events and Calculating Time Difference

lguinn2 — Fri, 18 Mar 2016 21:33:56 GMT

Try this first:

 index="wineventlog" SourceName="Backup Agent" (EventCode="1000" OR EventCode="1001") 
 | transaction host maxspan=4h startswith=(EventCode="1000") endswith=(EventCode="1001") 
 | table host,duration

All I did was add host to the transaction command. This should help, but it still may not be a good solution, if you have a long time range.
You could also try this:

 index="wineventlog" SourceName="Backup Agent" (EventCode="1000" OR EventCode="1001") 
| sort host,_time
| eval starttime=if(EventCode="1000",_time,null())
| eval endtime=if(EventCode="1001",_time,null())
| streamstats current=t window=2 global=f latest(starttime) as start latest(endtime) as end by host
| where isnotnull(endtime)
| eval duration=end-start

This solution should work with somewhat larger timeframes. I am not sure how well it will work if you have multiple backups for a single host.

Re: Correlating Different Events and Calculating Time Difference

somesoni2 — Fri, 18 Mar 2016 21:34:52 GMT

How many times these events can happen from one host in a day?

Re: Correlating Different Events and Calculating Time Difference

dw385 — Mon, 21 Mar 2016 12:04:19 GMT

Usually only one occurrence but its possible to see multiple in a day as jobs are restarted.