How to measure time difference between reoccurring events?

[samwatson45]

Hi,

I am currently trying to write a search which will accurately measure how long it takes for a customer to log in to an application. I have determined which events (within the IIS logs) signal the beginning and the end of this process. I currently have the following query, which works somewhat for what I am trying to do:

index=iis action_type=launch cs_method=GET cs_username=* customer_code=* 
 | eval full_user=customer_code+": "+cs_username
 | stats latest(_time) as time_login by full_user 
 | join full_user 
     [ search index=iis a=StartedShell cs_username=* customer_code=*
     | eval full_user=customer_code+": "+cs_username
     | stats latest(_time) as time_finish by full_user ] 
 | eval difference=time_finish-time_login 

The problem with this is that it is a certain customer, that has the same cs_username and customer_code, has multiple logins within one day then this query will only find the time difference for the latest one.

I am aware this is because I am using the latest(_time) calculation, however, I am not sure of another way to do it. I tried |eval time_login=_time and |eval time_finish=_time however then it gave me the time difference between the first login and then every completion of the login.

The issue is that IIS logs don't contain a sessionID, so there is nothing unique to each login event to distinguish them.
Is there any way to measure the amount of time for each individual login and make sure that each a=StartedShell event is linked to the correct action_type=launch event?

Many thanks.

[DalJeanis]

This is a case where streamstats is your best bet.

The general formula is (1) select your beginning and ending events (2) sort them into order by _time (3) copy the data you need forward from the prior event to the later event (4) throw away the earlier event (5) calculate your difference.

your search that gets beginning and ending events
| eval starttime=case(test that this is a start event, _time)
| eval keyfield = whatever you want to make sure start and end events match
| streamstats window=2 last(starttime) as starttime by key_field
| eval duration=case( test that this is an ending event, _time) - startime
| where isnotnull(duration)

In this case, I reversed steps 4 and 5 because it looks cleaner for this use case.

---

In some cases, you may have a series of steps and you are trying to figure out how long each one took to complete. That looks like this:

your search that selects events
| eval keyfield = whatever you want to make sure all the events match
| streamstats current=f window=1 last(_time) as prevtime 
| eval prevtime=coalesce(prevtime,_time)
| eval duration=_time-prevtime

[samwatson45]

For this I got

index=iis ((action_type=launch AND cs_method=GET ) OR (a=StartedShell)) cs_username=* customer_code=*
 | eval full_user=customer_code+": "+cs_username
 | eval starttime=case(action_type=launch AND cs_method=GET, _time)
 | eval keyfield=full_user
 | streamstats window=2 last(starttime) as starttime by key_field
 | eval duration=case(a=StartedShell,_time) - startime
 | where isnotnull(duration) 

Where the search did not return any results