Timing multiple event actions in IIS logs

[samwatson45]

Hi,

This is a bit of a long one so sorry in advance.

I am attempting to time some events which are happening in one of our products, which we can view with IIS logs. Because we want to see how long things are taking on the customers end of things, using the time_taken field gives us a huge under estimate.

Essentially we have (as an example) two seperate events which we know mark the beginning and the end of the login process. I'll call them action=login and action=end. The only real distinguishing features between separate login events are the customer and cs_username fields. However, is it possible to add on a distinction between multiple logins of the same person? For example each time customer=A and cs_username=A1 go through action=login it gets assigned a variable, either something unique or a counter of how many times that has happen. Then the same thing for action=end, so these can be paired up and every event monitored.

Another important factor that I need to take into account is if someone begins the login process but then it times out, and then they try again. This could look like:
- action=login,customer=A,cs_username=A1, _time=12:00
- action=login,customer=A,cs_username=A1, _time=12:05
- action=end,customer=A,cs_username=A1, _time=12:06
Where it would be important to pair the end with the second login, not the first.

If anyone has any ideas or has achieved something similar I would really appreciate it. I have beforehand used a search which takes the time difference between events but it can't do it for every login and doesn't account for unfinished actions.

Many thanks,
Sam

[somesoni2]

How do you want to time (time_taken) where login times out? Can a user open multiple windows and try login simultaneously or he/she can only start second login attempt after first one times out?

[samwatson45]

In theory they can try and login/perform actions at the same time in multiple windows, but for simplicity I think it's fair to ignore this.
I'm also not worried about trying to time events that do not complete.
Thanks.

[somesoni2]

Lets see if search like below gets you closer to your requirement (assuming fields action customer cs_username exists and _time is epoch timestamp for the event)

index=foo sourcetype=bar   action=login OR action=end
| sort 0 customer cs_username _time
| streamstats current=f window=1 values(_time) as prev_time values(action) as prev_action by customer cs_username
| where isnotnull(prev_time) AND action="end" AND prev_action="login"
| eval time_taken=_time-prev_time
| eval login_time=strftime(prev_time,"%F %T") | eval end_time=strftime(_time,"%F %T")
| table customer cs_username login_time end_time time_taken

[samwatson45]

This comment can be converted into an answer, thanks 🙂

[samwatson45]

Apologies for the late reply.

I've been experimenting with this search over the last few days. It hasn't been producing the results I'd like but I have concluded that is because our understanding of our own system is wrong! This search actually does what it is meant to perfectly, thanks for your help!